Liquibase changes not applied when updating from 1.9.x to 1.11.3

mario · May 27, 2015, 12:02pm

I have a database that I used with OpenMRS 1.9.9-Snapshot. Now I wanted to update my System to 1.11.3 using the mentioned DB.

Everything is in develop mode. So I cloned the openmrs-core and set it to 1.11.3 tag. Then compiled and started jetty. Now when starting I get an error telling me that deathdate_estimated is not present in the person table (error snippet below…)

Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLSyntaxErrorException: Unknown column ‘person0_.deathdate_estimated’ in ‘field list’

Checking the liquibaschangelog table I find that my latest entry from liquibase-update-to-latest.xml actually is ‘201401040440-TRUNK-3919’ (which is the latest to be found in the liquibase-update-to-latest.xml in 1.9.9-Snapshot)

All the changes after the one mentioned above are not applied. What did I miss when updating?

P.S. I run the latest CIEL version (20150514) and I don’t have any orders in the DB

raff · May 27, 2015, 12:18pm

Did you see the database upgrade wizard before the error? The system should have started in the upgrade mode asking to log in as an administrator to execute changesets. Wasn’t that the case?

mario · May 27, 2015, 12:20pm

No, I didn’t see the wizzard Jetty just started and threw that error along the way, and when I tried to go to the login page I would be redirected to http://localhost:8080/openmrs/initialsetup showing me the error’s stacktrace

raff · May 27, 2015, 12:32pm

Can you share the full stack trace from your server logs so we can find out which line of code leads to that error?

lluismf · May 27, 2015, 12:38pm

If the soft expects a deathdate_estimated column then it must exist a liquibase changeset to create it. Can you check the liquibase log to see if there was an error when it was created?

mario · May 27, 2015, 12:44pm

So this is the console logout after mvn jetty:run in the webapp folder

[INFO] Scanning for projects...
[WARNING] 
[WARNING] Some problems were encountered while building the effective model for org.openmrs.web:openmrs-webapp:war:1.11.3
[WARNING] 'reporting.plugins.plugin.version' for org.apache.maven.plugins:maven-javadoc-plugin is missing. @ org.openmrs:openmrs:1.11.3, /home/mario/git/openmrs-core/pom.xml, line 1090, column 12
[WARNING] 
[WARNING] It is highly recommended to fix these problems because they threaten the stability of your build.
[WARNING] 
[WARNING] For this reason, future Maven versions might no longer support building such malformed projects.
[WARNING] 
[INFO]                                                                         
[INFO] ------------------------------------------------------------------------
[INFO] Building openmrs-webapp 1.11.3
[INFO] ------------------------------------------------------------------------
[INFO] 
[INFO] >>> maven-jetty-plugin:6.1.10:run (default-cli) @ openmrs-webapp >>>
[INFO] 
[INFO] --- buildnumber-maven-plugin:1.1:create (default) @ openmrs-webapp ---
[INFO] Checking for local modifications: skipped.
[INFO] Updating project files from SCM: skipped.
[INFO] ShortRevision tag detected. The value is '6'.
[INFO] Executing: /bin/sh -c cd /home/mario/git/openmrs-core/webapp && git rev-parse --verify --short=6 HEAD
[INFO] Working directory: /home/mario/git/openmrs-core/webapp
[INFO] Storing buildNumber: 03b68a at timestamp: 1432729296878
[INFO] ShortRevision tag detected. The value is '6'.
[INFO] Executing: /bin/sh -c cd /home/mario/git/openmrs-core/webapp && git rev-parse --verify --short=6 HEAD
[INFO] Working directory: /home/mario/git/openmrs-core/webapp
[INFO] Storing buildScmBranch: UNKNOWN
[INFO] 
[INFO] --- build-helper-maven-plugin:1.5:parse-version (parse-version) @ openmrs-webapp ---
[INFO] 
[INFO] --- maven-resources-plugin:2.4:resources (default-resources) @ openmrs-webapp ---
[INFO] Using 'UTF-8' encoding to copy filtered resources.
[INFO] Copying 7 resources
[INFO] Copying 1 resource to ../jetty
[INFO] 
[INFO] --- maven-antrun-plugin:1.4:run (default) @ openmrs-webapp ---
project.artifactId
[INFO] Executing tasks
    [unzip] Expanding: /home/mario/git/openmrs-core/webapp/src/main/resources/liquibase-demo-data.zip into /home/mario/git/openmrs-core/webapp/target/classes
[INFO] Executed tasks
[INFO] 
[INFO] --- maven-compiler-plugin:2.1:compile (default-compile) @ openmrs-webapp ---
[INFO] No sources to compile
[INFO] 
[INFO] --- maven-resources-plugin:2.4:testResources (default-testResources) @ openmrs-webapp ---
[INFO] Using 'UTF-8' encoding to copy filtered resources.
[INFO] Copying 1 resource
[INFO] 
[INFO] --- maven-compiler-plugin:2.1:testCompile (default-testCompile) @ openmrs-webapp ---
[INFO] Nothing to compile - all classes are up to date
[INFO] 
[INFO] <<< maven-jetty-plugin:6.1.10:run (default-cli) @ openmrs-webapp <<<
[INFO] 
[INFO] --- maven-jetty-plugin:6.1.10:run (default-cli) @ openmrs-webapp ---
[INFO] Configuring Jetty for project: openmrs-webapp
[INFO] Webapp source directory = /home/mario/git/openmrs-core/webapp/src/main/webapp
[INFO] web.xml file = /home/mario/git/openmrs-core/webapp/target/jetty/WEB-INF/web.xml
[INFO] Classes = /home/mario/git/openmrs-core/webapp/target/classes
[INFO] Added extra scan target:/home/mario/git/openmrs-core/api/target/classes
[INFO] Added extra scan target:/home/mario/git/openmrs-core/web/target/classes
[INFO] Property OPENMRS_INSTALLATION_SCRIPT=null was set
2015-05-27 15:21:38.816::INFO:  Logging to STDERR via org.mortbay.log.StdErrLog
[INFO] Context path = /openmrs
[INFO] Tmp directory =  determined at runtime
[INFO] Web defaults = org/mortbay/jetty/webapp/webdefault.xml
[INFO] Web overrides = src/test/resources/override-web.xml
[INFO] Webapp directory = /home/mario/git/openmrs-core/webapp/src/main/webapp
[INFO] Starting jetty 6.1.10 ...
2015-05-27 15:21:38.827::INFO:  jetty-6.1.10
2015-05-27 15:21:39.453::INFO:  No Transaction manager found - if your webapp requires one, please configure one.
2015-05-27 15:21:39.053:/openmrs:INFO:  Set web app root system property: 'webapp.root' = [/home/mario/git/openmrs-core/webapp/src/main/webapp/]
2015-05-27 15:21:39.055:/openmrs:INFO:  Initializing log4j from [classpath:log4j.xml]
INFO 5/27/15 3:21 PM:liquibase: Reading from `liquibasechangelog`
WARNING 5/27/15 3:21 PM:liquibase: modifyDataType will lose primary key/autoincrement/not null settings for mysql.  Use <sql> and re-specify all configuration if this is the case
WARNING 5/27/15 3:21 PM:liquibase: modifyDataType will lose primary key/autoincrement/not null settings for mysql.  Use <sql> and re-specify all configuration if this is the case
WARNING 5/27/15 3:21 PM:liquibase: modifyDataType will lose primary key/autoincrement/not null settings for mysql.  Use <sql> and re-specify all configuration if this is the case
INFO - LocalSessionFactoryBean.buildSessionFactory(780) |2015-05-27 15:21:50,313| Building new Hibernate SessionFactory
ERROR - JDBCExceptionReporter.logExceptions(234) |2015-05-27 15:21:56,880| Unknown column 'person0_.deathdate_estimated' in 'field list'
ERROR - Listener.contextInitialized(174) |2015-05-27 15:21:56,885| Got exception while starting up: 
org.openmrs.module.ModuleException: Unable to start OpenMRS. Error thrown was: could not load an entity: [org.openmrs.Person#1]
        at org.openmrs.web.WebDaemon.startOpenmrs(WebDaemon.java:64)
        at org.openmrs.web.Listener.contextInitialized(Listener.java:168)
        at org.mortbay.jetty.handler.ContextHandler.startContext(ContextHandler.java:540)
        at org.mortbay.jetty.servlet.Context.startContext(Context.java:135)
        at org.mortbay.jetty.webapp.WebAppContext.startContext(WebAppContext.java:1220)
        at org.mortbay.jetty.handler.ContextHandler.doStart(ContextHandler.java:510)
        at org.mortbay.jetty.webapp.WebAppContext.doStart(WebAppContext.java:448)
        at org.mortbay.jetty.plugin.Jetty6PluginWebAppContext.doStart(Jetty6PluginWebAppContext.java:110)
        at org.mortbay.component.AbstractLifeCycle.start(AbstractLifeCycle.java:39)
        at org.mortbay.jetty.handler.HandlerCollection.doStart(HandlerCollection.java:152)
        at org.mortbay.jetty.handler.ContextHandlerCollection.doStart(ContextHandlerCollection.java:156)
        at org.mortbay.component.AbstractLifeCycle.start(AbstractLifeCycle.java:39)
        at org.mortbay.jetty.handler.HandlerCollection.doStart(HandlerCollection.java:152)
        at org.mortbay.component.AbstractLifeCycle.start(AbstractLifeCycle.java:39)
        at org.mortbay.jetty.handler.HandlerWrapper.doStart(HandlerWrapper.java:130)
        at org.mortbay.jetty.Server.doStart(Server.java:222)
        at org.mortbay.component.AbstractLifeCycle.start(AbstractLifeCycle.java:39)
        at org.mortbay.jetty.plugin.Jetty6PluginServer.start(Jetty6PluginServer.java:132)
        at org.mortbay.jetty.plugin.AbstractJettyMojo.startJetty(AbstractJettyMojo.java:371)
        at org.mortbay.jetty.plugin.AbstractJettyMojo.execute(AbstractJettyMojo.java:307)
        at org.mortbay.jetty.plugin.AbstractJettyRunMojo.execute(AbstractJettyRunMojo.java:203)
        at org.mortbay.jetty.plugin.Jetty6RunMojo.execute(Jetty6RunMojo.java:184)
        at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo(DefaultBuildPluginManager.java:101)
        at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:209)
        at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:153)
        at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:145)
        at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:84)
        at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:59)
        at org.apache.maven.lifecycle.internal.LifecycleStarter.singleThreadedBuild(LifecycleStarter.java:183)
        at org.apache.maven.lifecycle.internal.LifecycleStarter.execute(LifecycleStarter.java:161)
        at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:320)
        at org.apache.maven.DefaultMaven.execute(DefaultMaven.java:156)
        at org.apache.maven.cli.MavenCli.execute(MavenCli.java:537)
        at org.apache.maven.cli.MavenCli.doMain(MavenCli.java:196)
        at org.apache.maven.cli.MavenCli.main(MavenCli.java:141)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:606)
        at org.codehaus.plexus.classworlds.launcher.Launcher.launchEnhanced(Launcher.java:289)
        at org.codehaus.plexus.classworlds.launcher.Launcher.launch(Launcher.java:229)
        at org.codehaus.plexus.classworlds.launcher.Launcher.mainWithExitCode(Launcher.java:415)
        at org.codehaus.plexus.classworlds.launcher.Launcher.main(Launcher.java:356)
Caused by: org.hibernate.exception.SQLGrammarException: could not load an entity: [org.openmrs.Person#1]
        at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:92)
        at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:66)
        at org.hibernate.loader.Loader.loadEntity(Loader.java:2041)
        at org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:86)
        at org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:76)
        at org.hibernate.persister.entity.AbstractEntityPersister.load(AbstractEntityPersister.java:3293)
        at org.hibernate.event.def.DefaultLoadEventListener.loadFromDatasource(DefaultLoadEventListener.java:496)
        at org.hibernate.event.def.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:477)
        at org.hibernate.event.def.DefaultLoadEventListener.load(DefaultLoadEventListener.java:227)
        at org.hibernate.event.def.DefaultLoadEventListener.proxyOrLoad(DefaultLoadEventListener.java:285)
        at org.hibernate.event.def.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:152)
        at org.hibernate.impl.SessionImpl.fireLoad(SessionImpl.java:1090)
        at org.hibernate.impl.SessionImpl.internalLoad(SessionImpl.java:1038)
        at org.hibernate.type.EntityType.resolveIdentifier(EntityType.java:630)
        at org.hibernate.type.EntityType.resolve(EntityType.java:438)
        at org.hibernate.engine.TwoPhaseLoad.initializeEntity(TwoPhaseLoad.java:139)
        at org.hibernate.loader.Loader.initializeEntitiesAndCollections(Loader.java:982)
        at org.hibernate.loader.Loader.doQuery(Loader.java:857)
        at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:274)
        at org.hibernate.loader.Loader.doList(Loader.java:2533)
        at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2276)
        at org.hibernate.loader.Loader.list(Loader.java:2271)
        at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:452)
        at org.hibernate.hql.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:363)
        at org.hibernate.engine.query.HQLQueryPlan.performList(HQLQueryPlan.java:196)
        at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1268)
        at org.hibernate.impl.QueryImpl.list(QueryImpl.java:102)
        at org.hibernate.impl.AbstractQueryImpl.uniqueResult(AbstractQueryImpl.java:890)
        at org.openmrs.api.db.hibernate.HibernateContextDAO.getUserByUuid(HibernateContextDAO.java:215)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:606)
        at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
        at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:96)
        at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:260)
        at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:94)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
        at com.sun.proxy.$Proxy104.getUserByUuid(Unknown Source)
        at org.openmrs.api.context.Context.getAuthenticatedUser(Context.java:641)
        at org.openmrs.aop.AuthorizationAdvice.before(AuthorizationAdvice.java:51)
        at org.springframework.aop.framework.adapter.MethodBeforeAdviceInterceptor.invoke(MethodBeforeAdviceInterceptor.java:50)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
        at com.sun.proxy.$Proxy74.getGlobalProperty(Unknown Source)
        at org.openmrs.web.Listener.startOpenmrs(Listener.java:211)
        at org.openmrs.web.WebDaemon$1.run(WebDaemon.java:42)
Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLSyntaxErrorException: Unknown column 'person0_.deathdate_estimated' in 'field list'
        at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
        at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57)
        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
        at java.lang.reflect.Constructor.newInstance(Constructor.java:526)
        at com.mysql.jdbc.Util.handleNewInstance(Util.java:406)
        at com.mysql.jdbc.Util.getInstance(Util.java:381)
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1030)
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:956)
        at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3536)
        at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3468)
        at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1957)
        at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2107)
        at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2648)
        at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2086)
        at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:2237)
        at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeQuery(NewProxyPreparedStatement.java:76)
        at org.hibernate.jdbc.AbstractBatcher.getResultSet(AbstractBatcher.java:208)
        at org.hibernate.loader.Loader.getResultSet(Loader.java:1953)
        at org.hibernate.loader.Loader.doQuery(Loader.java:802)
        at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:274)
        at org.hibernate.loader.Loader.loadEntity(Loader.java:2037)
        ... 47 more
INFO 5/27/15 3:21 PM:liquibase: Reading from `liquibasechangelog`
WARNING 5/27/15 3:21 PM:liquibase: modifyDataType will lose primary key/autoincrement/not null settings for mysql.  Use <sql> and re-specify all configuration if this is the case
WARNING 5/27/15 3:21 PM:liquibase: modifyDataType will lose primary key/autoincrement/not null settings for mysql.  Use <sql> and re-specify all configuration if this is the case
WARNING 5/27/15 3:21 PM:liquibase: modifyDataType will lose primary key/autoincrement/not null settings for mysql.  Use <sql> and re-specify all configuration if this is the case
2015-05-27 15:21:59.752::INFO:  Started SelectChannelConnector@0.0.0.0:8080
[INFO] Started Jetty Server
[INFO] Starting scanner at interval of 10 seconds.

###################################### Then this is the stacktrace I get when being redirected to http://localhost:8080/openmrs/initialsetup

The following error occurred at startup:
Unable to start OpenMRS. Error thrown was: could not load an entity: [org.openmrs.Person#1]

org.openmrs.module.ModuleException: Unable to start OpenMRS. Error thrown was: could not load an entity: [org.openmrs.Person#1]
    at org.openmrs.web.WebDaemon.startOpenmrs(WebDaemon.java:64)
    at org.openmrs.web.Listener.contextInitialized(Listener.java:168)
    at org.mortbay.jetty.handler.ContextHandler.startContext(ContextHandler.java:540)
    at org.mortbay.jetty.servlet.Context.startContext(Context.java:135)
    at org.mortbay.jetty.webapp.WebAppContext.startContext(WebAppContext.java:1220)
    at org.mortbay.jetty.handler.ContextHandler.doStart(ContextHandler.java:510)
    at org.mortbay.jetty.webapp.WebAppContext.doStart(WebAppContext.java:448)
    at org.mortbay.jetty.plugin.Jetty6PluginWebAppContext.doStart(Jetty6PluginWebAppContext.java:110)
    at org.mortbay.component.AbstractLifeCycle.start(AbstractLifeCycle.java:39)
    at org.mortbay.jetty.handler.HandlerCollection.doStart(HandlerCollection.java:152)
    at org.mortbay.jetty.handler.ContextHandlerCollection.doStart(ContextHandlerCollection.java:156)
    at org.mortbay.component.AbstractLifeCycle.start(AbstractLifeCycle.java:39)
    at org.mortbay.jetty.handler.HandlerCollection.doStart(HandlerCollection.java:152)
    at org.mortbay.component.AbstractLifeCycle.start(AbstractLifeCycle.java:39)
    at org.mortbay.jetty.handler.HandlerWrapper.doStart(HandlerWrapper.java:130)
    at org.mortbay.jetty.Server.doStart(Server.java:222)
    at org.mortbay.component.AbstractLifeCycle.start(AbstractLifeCycle.java:39)
    at org.mortbay.jetty.plugin.Jetty6PluginServer.start(Jetty6PluginServer.java:132)
    at org.mortbay.jetty.plugin.AbstractJettyMojo.startJetty(AbstractJettyMojo.java:371)
    at org.mortbay.jetty.plugin.AbstractJettyMojo.execute(AbstractJettyMojo.java:307)
    at org.mortbay.jetty.plugin.AbstractJettyRunMojo.execute(AbstractJettyRunMojo.java:203)
    at org.mortbay.jetty.plugin.Jetty6RunMojo.execute(Jetty6RunMojo.java:184)
    at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo(DefaultBuildPluginManager.java:101)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:209)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:153)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:145)
    at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:84)
    at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:59)
    at org.apache.maven.lifecycle.internal.LifecycleStarter.singleThreadedBuild(LifecycleStarter.java:183)
    at org.apache.maven.lifecycle.internal.LifecycleStarter.execute(LifecycleStarter.java:161)
    at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:320)
    at org.apache.maven.DefaultMaven.execute(DefaultMaven.java:156)
    at org.apache.maven.cli.MavenCli.execute(MavenCli.java:537)
    at org.apache.maven.cli.MavenCli.doMain(MavenCli.java:196)
    at org.apache.maven.cli.MavenCli.main(MavenCli.java:141)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:606)
    at org.codehaus.plexus.classworlds.launcher.Launcher.launchEnhanced(Launcher.java:289)
    at org.codehaus.plexus.classworlds.launcher.Launcher.launch(Launcher.java:229)
    at org.codehaus.plexus.classworlds.launcher.Launcher.mainWithExitCode(Launcher.java:415)
    at org.codehaus.plexus.classworlds.launcher.Launcher.main(Launcher.java:356)
Caused by: org.hibernate.exception.SQLGrammarException: could not load an entity: [org.openmrs.Person#1]
    at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:92)
    at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:66)
    at org.hibernate.loader.Loader.loadEntity(Loader.java:2041)
    at org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:86)
    at org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:76)
    at org.hibernate.persister.entity.AbstractEntityPersister.load(AbstractEntityPersister.java:3293)
    at org.hibernate.event.def.DefaultLoadEventListener.loadFromDatasource(DefaultLoadEventListener.java:496)
    at org.hibernate.event.def.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:477)
    at org.hibernate.event.def.DefaultLoadEventListener.load(DefaultLoadEventListener.java:227)
    at org.hibernate.event.def.DefaultLoadEventListener.proxyOrLoad(DefaultLoadEventListener.java:285)
    at org.hibernate.event.def.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:152)
    at org.hibernate.impl.SessionImpl.fireLoad(SessionImpl.java:1090)
    at org.hibernate.impl.SessionImpl.internalLoad(SessionImpl.java:1038)
    at org.hibernate.type.EntityType.resolveIdentifier(EntityType.java:630)
    at org.hibernate.type.EntityType.resolve(EntityType.java:438)
    at org.hibernate.engine.TwoPhaseLoad.initializeEntity(TwoPhaseLoad.java:139)
    at org.hibernate.loader.Loader.initializeEntitiesAndCollections(Loader.java:982)
    at org.hibernate.loader.Loader.doQuery(Loader.java:857)
    at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:274)
    at org.hibernate.loader.Loader.doList(Loader.java:2533)
    at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2276)
    at org.hibernate.loader.Loader.list(Loader.java:2271)
    at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:452)
    at org.hibernate.hql.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:363)
    at org.hibernate.engine.query.HQLQueryPlan.performList(HQLQueryPlan.java:196)
    at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1268)
    at org.hibernate.impl.QueryImpl.list(QueryImpl.java:102)
    at org.hibernate.impl.AbstractQueryImpl.uniqueResult(AbstractQueryImpl.java:890)
    at org.openmrs.api.db.hibernate.HibernateContextDAO.getUserByUuid(HibernateContextDAO.java:215)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:606)
    at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
    at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:96)
    at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:260)
    at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:94)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
    at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
    at com.sun.proxy.$Proxy104.getUserByUuid(Unknown Source)
    at org.openmrs.api.context.Context.getAuthenticatedUser(Context.java:641)
    at org.openmrs.aop.AuthorizationAdvice.before(AuthorizationAdvice.java:51)
    at org.springframework.aop.framework.adapter.MethodBeforeAdviceInterceptor.invoke(MethodBeforeAdviceInterceptor.java:50)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
    at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
    at com.sun.proxy.$Proxy74.getGlobalProperty(Unknown Source)
    at org.openmrs.web.Listener.startOpenmrs(Listener.java:211)
    at org.openmrs.web.WebDaemon$1.run(WebDaemon.java:42)
Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLSyntaxErrorException: Unknown column 'person0_.deathdate_estimated' in 'field list'
    at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
    at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57)
    at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
    at java.lang.reflect.Constructor.newInstance(Constructor.java:526)
    at com.mysql.jdbc.Util.handleNewInstance(Util.java:406)
    at com.mysql.jdbc.Util.getInstance(Util.java:381)
    at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1030)
    at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:956)
    at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3536)
    at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3468)
    at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1957)
    at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2107)
    at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2648)
    at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2086)
    at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:2237)
    at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeQuery(NewProxyPreparedStatement.java:76)
    at org.hibernate.jdbc.AbstractBatcher.getResultSet(AbstractBatcher.java:208)
    at org.hibernate.loader.Loader.getResultSet(Loader.java:1953)
    at org.hibernate.loader.Loader.doQuery(Loader.java:802)
    at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:274)
    at org.hibernate.loader.Loader.loadEntity(Loader.java:2037)
    ... 47 more


See the server log for full output.

mario · May 27, 2015, 12:47pm

@lluismf There is a changeset for that in liquibase-update-to-latest.xml. It’s just not applied to my database.

mario · May 27, 2015, 3:07pm

I found that if I add the column manually by running

ALTER TABLE person ADD deathdate_estimated BOOLEAN

and then restart jetty, it would apply the latest liquibase-update-to-latest.xml changesets. Some fail due to unmet preconditions-

Yet I feel that this should not be the recommended way, right?

raff · May 29, 2015, 1:57pm

@mario, I have tried upgrading from 1.9.x to 1.11.3 and the liquibase changesets did run for me correctly. In your case for some reason no new changes were found by liquibase. Did you run mvn clean install before trying to run jetty? Maybe files haven’t been refreshed properly.

mario · June 2, 2015, 8:32am

Thanks so much @raff to try it out. I did mvn clean install before I started jetty. Can the problem be the maven version? So far I tried 3.0.5 and 3.2.1

raff · June 2, 2015, 9:56am

Are you saying that you were able to reproduce the issue using maven 3.0.5 and 3.2.1?

I’m using maven 3.0.5.

mario · June 2, 2015, 10:49am

Yes. So far using another version of maven didn’t solve the issue…

raff · June 2, 2015, 11:05am

Could you please try changing the log level in log4j.xml to DEBUG for org.openmrs and org.openmrs.api? Then please paste the server log again.

mario · June 3, 2015, 11:19am

@raff: this is what I get when I run jetty in debug mode

[INFO] Scanning for projects...
[INFO]                                                                         
[INFO] ------------------------------------------------------------------------
[INFO] Building openmrs-webapp 1.11.3
[INFO] ------------------------------------------------------------------------
[INFO] 
[INFO] >>> maven-jetty-plugin:6.1.10:run (default-cli) > test-compile @ openmrs-webapp >>>
[INFO] 
[INFO] --- buildnumber-maven-plugin:1.1:create (default) @ openmrs-webapp ---
[INFO] Checking for local modifications: skipped.
[INFO] Updating project files from SCM: skipped.
[INFO] ShortRevision tag detected. The value is '6'.
[INFO] Executing: /bin/sh -c cd /home/mario/git/openmrs-core/webapp && git rev-parse --verify --short=6 HEAD
[INFO] Working directory: /home/mario/git/openmrs-core/webapp
[INFO] Storing buildNumber: 03b68a at timestamp: 1433329506524
[INFO] ShortRevision tag detected. The value is '6'.
[INFO] Executing: /bin/sh -c cd /home/mario/git/openmrs-core/webapp && git rev-parse --verify --short=6 HEAD
[INFO] Working directory: /home/mario/git/openmrs-core/webapp
[INFO] Storing buildScmBranch: UNKNOWN
[INFO] 
[INFO] --- build-helper-maven-plugin:1.5:parse-version (parse-version) @ openmrs-webapp ---
[INFO] 
[INFO] --- maven-resources-plugin:2.4:resources (default-resources) @ openmrs-webapp ---
[INFO] Using 'UTF-8' encoding to copy filtered resources.
[INFO] Copying 7 resources
[INFO] Copying 1 resource to ../jetty
[INFO] 
[INFO] --- maven-antrun-plugin:1.4:run (default) @ openmrs-webapp ---
project.artifactId
[INFO] Executing tasks
    [unzip] Expanding: /home/mario/git/openmrs-core/webapp/src/main/resources/liquibase-demo-data.zip into /home/mario/git/openmrs-core/webapp/target/classes
[INFO] Executed tasks
[INFO] 
[INFO] --- maven-compiler-plugin:2.1:compile (default-compile) @ openmrs-webapp ---
[INFO] No sources to compile
[INFO] 
[INFO] --- maven-resources-plugin:2.4:testResources (default-testResources) @ openmrs-webapp ---
[INFO] Using 'UTF-8' encoding to copy filtered resources.
[INFO] Copying 1 resource
[INFO] 
[INFO] --- maven-compiler-plugin:2.1:testCompile (default-testCompile) @ openmrs-webapp ---
[INFO] Nothing to compile - all classes are up to date
[INFO] 
[INFO] <<< maven-jetty-plugin:6.1.10:run (default-cli) < test-compile @ openmrs-webapp <<<
[INFO] 
[INFO] --- maven-jetty-plugin:6.1.10:run (default-cli) @ openmrs-webapp ---
[INFO] Configuring Jetty for project: openmrs-webapp
[INFO] Webapp source directory = /home/mario/git/openmrs-core/webapp/src/main/webapp
[INFO] web.xml file = /home/mario/git/openmrs-core/webapp/target/jetty/WEB-INF/web.xml
[INFO] Classes = /home/mario/git/openmrs-core/webapp/target/classes
[INFO] Added extra scan target:/home/mario/git/openmrs-core/api/target/classes
[INFO] Added extra scan target:/home/mario/git/openmrs-core/web/target/classes
[INFO] Property OPENMRS_INSTALLATION_SCRIPT=null was set
[INFO] Logging to org.slf4j.impl.SimpleLogger(org.mortbay.log) via org.mortbay.log.Slf4jLog
[INFO] Context path = /openmrs
[INFO] Tmp directory =  determined at runtime
[INFO] Web defaults = org/mortbay/jetty/webapp/webdefault.xml
[INFO] Web overrides = src/test/resources/override-web.xml
[INFO] Webapp directory = /home/mario/git/openmrs-core/webapp/src/main/webapp
[INFO] Starting jetty 6.1.10 ...
[INFO] jetty-6.1.10
[INFO] No Transaction manager found - if your webapp requires one, please configure one.
[INFO] Set web app root system property: 'webapp.root' = [/home/mario/git/openmrs-core/webapp/src/main/webapp/]
[INFO] Initializing log4j from [classpath:log4j.xml]
DEBUG - Listener.contextInitialized(126) |2015-06-03 14:05:09,386| Starting the OpenMRS webapp
DEBUG - OpenmrsUtil.getRuntimePropertiesFilePathName(2665) |2015-06-03 14:05:09,459| Attempting to look for properties file in current directory: openmrs-runtime.properties
INFO - OpenmrsUtil.getRuntimeProperties(2625) |2015-06-03 14:05:09,461| Using runtime properties file: openmrs-runtime.properties
DEBUG - OpenmrsClassLoader.<init>(89) |2015-06-03 14:05:09,467| Creating new OpenmrsClassLoader instance with parent: ContextLoader@OpenMRS
DEBUG - DatabaseUpdater.updatesRequired(259) |2015-06-03 14:05:09,472| checking for updates
DEBUG - DatabaseUpdater.getUnrunDatabaseChanges(608) |2015-06-03 14:05:09,473| Getting unrun changesets
INFO 6/3/15 2:05 PM:liquibase: Reading from `liquibasechangelog`
WARNING 6/3/15 2:05 PM:liquibase: modifyDataType will lose primary key/autoincrement/not null settings for mysql.  Use <sql> and re-specify all configuration if this is the case
WARNING 6/3/15 2:05 PM:liquibase: modifyDataType will lose primary key/autoincrement/not null settings for mysql.  Use <sql> and re-specify all configuration if this is the case
WARNING 6/3/15 2:05 PM:liquibase: modifyDataType will lose primary key/autoincrement/not null settings for mysql.  Use <sql> and re-specify all configuration if this is the case
DEBUG - HibernateSessionFactoryBean.newConfiguration(62) |2015-06-03 14:05:18,206| Configuring hibernate sessionFactory properties
DEBUG - HibernateSessionFactoryBean.newConfiguration(106) |2015-06-03 14:05:18,208| Replacing variables in hibernate properties
DEBUG - HibernateSessionFactoryBean.newConfiguration(115) |2015-06-03 14:05:18,211| Setting global Hibernate Session Interceptor for SessionFactory, Interceptor: org.openmrs.api.db.hibernate.ChainingInterceptor@2f382d6e
DEBUG - ChainingInterceptor.addInterceptor(54) |2015-06-03 14:05:18,214| Adding org.openmrs.api.db.hibernate.AuditableInterceptor@5f888a65 to interceptor chain
DEBUG - ChainingInterceptor.addInterceptor(54) |2015-06-03 14:05:18,215| Adding org.openmrs.api.db.hibernate.ImmutableOrderInterceptor@6be420a6 to interceptor chain
INFO - LocalSessionFactoryBean.buildSessionFactory(780) |2015-06-03 14:05:20,695| Building new Hibernate SessionFactory
DEBUG - MessageSourceServiceImpl.setActiveMessageSource(70) |2015-06-03 14:05:23,035| Setting activeMessageSource: org.openmrs.messagesource.impl.MutableResourceBundleMessageSource: basenames=[/WEB-INF/custom_messages,/WEB-INF/module_messages,/WEB-INF/messages]
DEBUG - EventListeners.setGlobalPropertyListeners(48) |2015-06-03 14:05:23,160| GlobalPropertyListeners set to: org.openmrs.util.LocaleUtility, org.openmrs.util.LocationUtility, org.openmrs.api.impl.PersonNameGlobalPropertyListener, org.openmrs.api.impl.GlobalLocaleList, com.sun.proxy.$Proxy61, com.sun.proxy.$Proxy62
DEBUG - ServiceContext.<init>(122) |2015-06-03 14:05:23,165| Instantiating service context
DEBUG - ServiceContext.setService(765) |2015-06-03 14:05:24,059| Setting service: interface org.openmrs.api.PatientService
DEBUG - ServiceContext.setService(794) |2015-06-03 14:05:24,060| Service: interface org.openmrs.api.PatientService set successfully
DEBUG - ServiceContext.setService(765) |2015-06-03 14:05:24,060| Setting service: interface org.openmrs.api.PersonService
DEBUG - ServiceContext.setService(794) |2015-06-03 14:05:24,061| Service: interface org.openmrs.api.PersonService set successfully
DEBUG - ServiceContext.setService(765) |2015-06-03 14:05:24,062| Setting service: interface org.openmrs.api.ConceptService
DEBUG - ServiceContext.setService(794) |2015-06-03 14:05:24,063| Service: interface org.openmrs.api.ConceptService set successfully
DEBUG - ServiceContext.setService(765) |2015-06-03 14:05:24,064| Setting service: interface org.openmrs.api.UserService
DEBUG - ServiceContext.setService(794) |2015-06-03 14:05:24,065| Service: interface org.openmrs.api.UserService set successfully
DEBUG - ServiceContext.setService(765) |2015-06-03 14:05:24,066| Setting service: interface org.openmrs.api.ObsService
DEBUG - ServiceContext.setService(794) |2015-06-03 14:05:24,066| Service: interface org.openmrs.api.ObsService set successfully
DEBUG - ServiceContext.setService(765) |2015-06-03 14:05:24,067| Setting service: interface org.openmrs.api.EncounterService
DEBUG - ServiceContext.setService(794) |2015-06-03 14:05:24,068| Service: interface org.openmrs.api.EncounterService set successfully
DEBUG - ServiceContext.setService(765) |2015-06-03 14:05:24,069| Setting service: interface org.openmrs.api.LocationService
DEBUG - ServiceContext.setService(794) |2015-06-03 14:05:24,070| Service: interface org.openmrs.api.LocationService set successfully
DEBUG - ServiceContext.setService(765) |2015-06-03 14:05:24,071| Setting service: interface org.openmrs.api.OrderService
DEBUG - ServiceContext.setService(794) |2015-06-03 14:05:24,072| Service: interface org.openmrs.api.OrderService set successfully
DEBUG - ServiceContext.setService(765) |2015-06-03 14:05:24,073| Setting service: interface org.openmrs.api.FormService
DEBUG - ServiceContext.setService(794) |2015-06-03 14:05:24,073| Service: interface org.openmrs.api.FormService set successfully
DEBUG - ServiceContext.setService(765) |2015-06-03 14:05:24,074| Setting service: interface org.openmrs.api.AdministrationService
DEBUG - ServiceContext.setService(794) |2015-06-03 14:05:24,074| Service: interface org.openmrs.api.AdministrationService set successfully
DEBUG - ServiceContext.setService(765) |2015-06-03 14:05:24,075| Setting service: interface org.openmrs.api.DatatypeService
DEBUG - ServiceContext.setService(794) |2015-06-03 14:05:24,076| Service: interface org.openmrs.api.DatatypeService set successfully
DEBUG - ServiceContext.setService(765) |2015-06-03 14:05:24,076| Setting service: interface org.openmrs.api.ProgramWorkflowService
DEBUG - ServiceContext.setService(794) |2015-06-03 14:05:24,077| Service: interface org.openmrs.api.ProgramWorkflowService set successfully
DEBUG - ServiceContext.setService(765) |2015-06-03 14:05:24,078| Setting service: interface org.openmrs.api.PatientSetService
DEBUG - ServiceContext.setService(794) |2015-06-03 14:05:24,078| Service: interface org.openmrs.api.PatientSetService set successfully
DEBUG - ServiceContext.setService(765) |2015-06-03 14:05:24,079| Setting service: interface org.openmrs.api.CohortService
DEBUG - ServiceContext.setService(794) |2015-06-03 14:05:24,079| Service: interface org.openmrs.api.CohortService set successfully
DEBUG - ServiceContext.setService(765) |2015-06-03 14:05:24,080| Setting service: interface org.openmrs.notification.MessageService
DEBUG - ServiceContext.setService(794) |2015-06-03 14:05:24,080| Service: interface org.openmrs.notification.MessageService set successfully
DEBUG - ServiceContext.setService(765) |2015-06-03 14:05:24,081| Setting service: interface org.openmrs.api.SerializationService
DEBUG - ServiceContext.setService(794) |2015-06-03 14:05:24,081| Service: interface org.openmrs.api.SerializationService set successfully
DEBUG - ServiceContext.setService(765) |2015-06-03 14:05:24,082| Setting service: interface org.openmrs.scheduler.SchedulerService
DEBUG - ServiceContext.setService(794) |2015-06-03 14:05:24,083| Service: interface org.openmrs.scheduler.SchedulerService set successfully
DEBUG - ServiceContext.setService(765) |2015-06-03 14:05:24,083| Setting service: interface org.openmrs.notification.AlertService
DEBUG - ServiceContext.setService(794) |2015-06-03 14:05:24,084| Service: interface org.openmrs.notification.AlertService set successfully
DEBUG - ServiceContext.setService(765) |2015-06-03 14:05:24,084| Setting service: interface org.openmrs.api.ReportService
DEBUG - ServiceContext.setService(794) |2015-06-03 14:05:24,085| Service: interface org.openmrs.api.ReportService set successfully
DEBUG - ServiceContext.setService(765) |2015-06-03 14:05:24,085| Setting service: interface org.openmrs.reporting.ReportObjectService
DEBUG - ServiceContext.setService(794) |2015-06-03 14:05:24,086| Service: interface org.openmrs.reporting.ReportObjectService set successfully
DEBUG - ServiceContext.setService(765) |2015-06-03 14:05:24,086| Setting service: interface org.openmrs.api.DataSetService
DEBUG - ServiceContext.setService(794) |2015-06-03 14:05:24,087| Service: interface org.openmrs.api.DataSetService set successfully
DEBUG - ServiceContext.setService(765) |2015-06-03 14:05:24,087| Setting service: interface org.openmrs.hl7.HL7Service
DEBUG - ServiceContext.setService(794) |2015-06-03 14:05:24,088| Service: interface org.openmrs.hl7.HL7Service set successfully
DEBUG - ServiceContext.setService(765) |2015-06-03 14:05:24,089| Setting service: interface org.openmrs.arden.ArdenService
DEBUG - ServiceContext.setService(794) |2015-06-03 14:05:24,089| Service: interface org.openmrs.arden.ArdenService set successfully
DEBUG - ServiceContext.setService(765) |2015-06-03 14:05:24,090| Setting service: interface org.openmrs.messagesource.MessageSourceService
DEBUG - ServiceContext.setService(794) |2015-06-03 14:05:24,090| Service: interface org.openmrs.messagesource.MessageSourceService set successfully
DEBUG - ServiceContext.setService(765) |2015-06-03 14:05:24,091| Setting service: interface org.openmrs.api.ActiveListService
DEBUG - ServiceContext.setService(794) |2015-06-03 14:05:24,091| Service: interface org.openmrs.api.ActiveListService set successfully
DEBUG - ServiceContext.setService(765) |2015-06-03 14:05:24,092| Setting service: interface org.openmrs.api.VisitService
DEBUG - ServiceContext.setService(794) |2015-06-03 14:05:24,092| Service: interface org.openmrs.api.VisitService set successfully
DEBUG - ServiceContext.setService(765) |2015-06-03 14:05:24,093| Setting service: interface org.openmrs.api.ProviderService
DEBUG - ServiceContext.setService(794) |2015-06-03 14:05:24,094| Service: interface org.openmrs.api.ProviderService set successfully
DEBUG - ServiceContext.setService(765) |2015-06-03 14:05:24,094| Setting service: interface org.openmrs.notification.NoteService
DEBUG - ServiceContext.setService(794) |2015-06-03 14:05:24,095| Service: interface org.openmrs.notification.NoteService set successfully
DEBUG - EventListeners.setGlobalPropertyListeners(48) |2015-06-03 14:05:27,281| GlobalPropertyListeners set to: org.openmrs.web.controller.PseudoStaticContentController, org.openmrs.web.dwr.DWRPatientService, org.openmrs.web.WebUtil
DEBUG - HibernateContextDAO.openSession(257) |2015-06-03 14:05:27,300| HibernateContext: Opening Hibernate Session
DEBUG - HibernateContextDAO.openSession(265) |2015-06-03 14:05:27,310| Registering session with synchronization manager (1924884134)
DEBUG - AuthorizationAdvice.before(48) |2015-06-03 14:05:27,371| Calling authorization advice before getGlobalProperty
ERROR - JDBCExceptionReporter.logExceptions(234) |2015-06-03 14:05:27,576| Unknown column 'person0_.deathdate_estimated' in 'field list'
DEBUG - HibernateContextDAO.closeSession(277) |2015-06-03 14:05:27,579| HibernateContext: closing Hibernate Session
DEBUG - HibernateContextDAO.closeSession(279) |2015-06-03 14:05:27,579| Unbinding session from synchronization manager (1924884134)
ERROR - Listener.contextInitialized(174) |2015-06-03 14:05:27,580| Got exception while starting up: 
org.openmrs.module.ModuleException: Unable to start OpenMRS. Error thrown was: could not load an entity: [org.openmrs.Person#1]
        at org.openmrs.web.WebDaemon.startOpenmrs(WebDaemon.java:64)
        at org.openmrs.web.Listener.contextInitialized(Listener.java:168)
        at org.mortbay.jetty.handler.ContextHandler.startContext(ContextHandler.java:540)
        at org.mortbay.jetty.servlet.Context.startContext(Context.java:135)
        at org.mortbay.jetty.webapp.WebAppContext.startContext(WebAppContext.java:1220)
        at org.mortbay.jetty.handler.ContextHandler.doStart(ContextHandler.java:510)
        at org.mortbay.jetty.webapp.WebAppContext.doStart(WebAppContext.java:448)
        at org.mortbay.jetty.plugin.Jetty6PluginWebAppContext.doStart(Jetty6PluginWebAppContext.java:110)
        at org.mortbay.component.AbstractLifeCycle.start(AbstractLifeCycle.java:39)
        at org.mortbay.jetty.handler.HandlerCollection.doStart(HandlerCollection.java:152)
        at org.mortbay.jetty.handler.ContextHandlerCollection.doStart(ContextHandlerCollection.java:156)
        at org.mortbay.component.AbstractLifeCycle.start(AbstractLifeCycle.java:39)
        at org.mortbay.jetty.handler.HandlerCollection.doStart(HandlerCollection.java:152)
        at org.mortbay.component.AbstractLifeCycle.start(AbstractLifeCycle.java:39)
        at org.mortbay.jetty.handler.HandlerWrapper.doStart(HandlerWrapper.java:130)
        at org.mortbay.jetty.Server.doStart(Server.java:222)
        at org.mortbay.component.AbstractLifeCycle.start(AbstractLifeCycle.java:39)
        at org.mortbay.jetty.plugin.Jetty6PluginServer.start(Jetty6PluginServer.java:132)
        at org.mortbay.jetty.plugin.AbstractJettyMojo.startJetty(AbstractJettyMojo.java:371)
        at org.mortbay.jetty.plugin.AbstractJettyMojo.execute(AbstractJettyMojo.java:307)
        at org.mortbay.jetty.plugin.AbstractJettyRunMojo.execute(AbstractJettyRunMojo.java:203)
        at org.mortbay.jetty.plugin.Jetty6RunMojo.execute(Jetty6RunMojo.java:184)
        at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo(DefaultBuildPluginManager.java:134)
        at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:208)
        at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:153)
        at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:145)
        at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:116)
        at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:80)
        at org.apache.maven.lifecycle.internal.builder.singlethreaded.SingleThreadedBuilder.build(SingleThreadedBuilder.java:51)
        at org.apache.maven.lifecycle.internal.LifecycleStarter.execute(LifecycleStarter.java:128)
        at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:307)
        at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:193)
        at org.apache.maven.DefaultMaven.execute(DefaultMaven.java:106)
        at org.apache.maven.cli.MavenCli.execute(MavenCli.java:862)
        at org.apache.maven.cli.MavenCli.doMain(MavenCli.java:286)
        at org.apache.maven.cli.MavenCli.main(MavenCli.java:197)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:606)
        at org.codehaus.plexus.classworlds.launcher.Launcher.launchEnhanced(Launcher.java:289)
        at org.codehaus.plexus.classworlds.launcher.Launcher.launch(Launcher.java:229)
        at org.codehaus.plexus.classworlds.launcher.Launcher.mainWithExitCode(Launcher.java:415)
        at org.codehaus.plexus.classworlds.launcher.Launcher.main(Launcher.java:356)
Caused by: org.hibernate.exception.SQLGrammarException: could not load an entity: [org.openmrs.Person#1]
        at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:92)
        at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:66)
        at org.hibernate.loader.Loader.loadEntity(Loader.java:2041)
        at org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:86)
        at org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:76)
        at org.hibernate.persister.entity.AbstractEntityPersister.load(AbstractEntityPersister.java:3293)
        at org.hibernate.event.def.DefaultLoadEventListener.loadFromDatasource(DefaultLoadEventListener.java:496)
        at org.hibernate.event.def.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:477)
        at org.hibernate.event.def.DefaultLoadEventListener.load(DefaultLoadEventListener.java:227)
        at org.hibernate.event.def.DefaultLoadEventListener.proxyOrLoad(DefaultLoadEventListener.java:285)
        at org.hibernate.event.def.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:152)
        at org.hibernate.impl.SessionImpl.fireLoad(SessionImpl.java:1090)
        at org.hibernate.impl.SessionImpl.internalLoad(SessionImpl.java:1038)
        at org.hibernate.type.EntityType.resolveIdentifier(EntityType.java:630)
        at org.hibernate.type.EntityType.resolve(EntityType.java:438)
        at org.hibernate.engine.TwoPhaseLoad.initializeEntity(TwoPhaseLoad.java:139)
        at org.hibernate.loader.Loader.initializeEntitiesAndCollections(Loader.java:982)
        at org.hibernate.loader.Loader.doQuery(Loader.java:857)
        at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:274)
        at org.hibernate.loader.Loader.doList(Loader.java:2533)
        at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2276)
        at org.hibernate.loader.Loader.list(Loader.java:2271)
        at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:452)
        at org.hibernate.hql.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:363)
        at org.hibernate.engine.query.HQLQueryPlan.performList(HQLQueryPlan.java:196)
        at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1268)
        at org.hibernate.impl.QueryImpl.list(QueryImpl.java:102)
        at org.hibernate.impl.AbstractQueryImpl.uniqueResult(AbstractQueryImpl.java:890)
        at org.openmrs.api.db.hibernate.HibernateContextDAO.getUserByUuid(HibernateContextDAO.java:215)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:606)
        at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
        at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:96)
        at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:260)
        at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:94)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
        at com.sun.proxy.$Proxy113.getUserByUuid(Unknown Source)
        at org.openmrs.api.context.Context.getAuthenticatedUser(Context.java:641)
        at org.openmrs.aop.AuthorizationAdvice.before(AuthorizationAdvice.java:51)
        at org.springframework.aop.framework.adapter.MethodBeforeAdviceInterceptor.invoke(MethodBeforeAdviceInterceptor.java:50)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
        at com.sun.proxy.$Proxy83.getGlobalProperty(Unknown Source)
        at org.openmrs.web.Listener.startOpenmrs(Listener.java:211)
        at org.openmrs.web.WebDaemon$1.run(WebDaemon.java:42)
Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLSyntaxErrorException: Unknown column 'person0_.deathdate_estimated' in 'field list'
        at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
        at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57)
        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
        at java.lang.reflect.Constructor.newInstance(Constructor.java:526)
        at com.mysql.jdbc.Util.handleNewInstance(Util.java:406)
        at com.mysql.jdbc.Util.getInstance(Util.java:381)
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1030)
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:956)
        at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3536)
        at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3468)
        at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1957)
        at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2107)
        at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2648)
        at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2086)
        at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:2237)
        at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeQuery(NewProxyPreparedStatement.java:76)
        at org.hibernate.jdbc.AbstractBatcher.getResultSet(AbstractBatcher.java:208)
        at org.hibernate.loader.Loader.getResultSet(Loader.java:1953)
        at org.hibernate.loader.Loader.doQuery(Loader.java:802)
        at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:274)
        at org.hibernate.loader.Loader.loadEntity(Loader.java:2037)
        ... 47 more
DEBUG - OpenmrsUtil.getRuntimePropertiesFilePathName(2665) |2015-06-03 14:05:27,666| Attempting to look for properties file in current directory: openmrs-runtime.properties
INFO - OpenmrsUtil.getRuntimeProperties(2625) |2015-06-03 14:05:27,667| Using runtime properties file: openmrs-runtime.properties
INFO - DatabaseUtil.loadDatabaseDriver(91) |2015-06-03 14:05:27,669| Set database driver class as com.mysql.jdbc.Driver
DEBUG - UpdateFilter.init(454) |2015-06-03 14:05:27,690| Initializing the UpdateFilter
DEBUG - DatabaseUpdater.getUnrunDatabaseChanges(608) |2015-06-03 14:05:27,691| Getting unrun changesets
INFO 6/3/15 2:05 PM:liquibase: Reading from `liquibasechangelog`
WARNING 6/3/15 2:05 PM:liquibase: modifyDataType will lose primary key/autoincrement/not null settings for mysql.  Use <sql> and re-specify all configuration if this is the case
WARNING 6/3/15 2:05 PM:liquibase: modifyDataType will lose primary key/autoincrement/not null settings for mysql.  Use <sql> and re-specify all configuration if this is the case
WARNING 6/3/15 2:05 PM:liquibase: modifyDataType will lose primary key/autoincrement/not null settings for mysql.  Use <sql> and re-specify all configuration if this is the case
DEBUG - GenericFilterBean.init(172) |2015-06-03 14:05:30,533| Initializing filter 'OpenmrsFilter'
DEBUG - GenericFilterBean.init(197) |2015-06-03 14:05:30,534| Filter 'OpenmrsFilter' configured successfully
DEBUG - ModuleFilter.init(37) |2015-06-03 14:05:30,534| Initializating ModuleFilter
DEBUG - GenericFilterBean.init(172) |2015-06-03 14:05:30,536| Initializing filter 'compressionFilter'
DEBUG - GenericFilterBean.init(197) |2015-06-03 14:05:30,536| Filter 'compressionFilter' configured successfully
[INFO] Started SelectChannelConnector@0.0.0.0:8080
[INFO] Started Jetty Server
[INFO] Starting scanner at interval of 10 seconds.

And btw. this is my current openmrs-runtime-properties configuration. Just to make sure that this doesn’t cause problems (I would be surprised if it would though…)

module.allow_web_admin=true
auto_update_database=true
connection.username=myuser
connection.password=myPwd

application_data_directory=/path/to/my/directory
connection.url=jdbc:mysql://localhost:3306/openmrs?autoReconnect=true&sessionVariables=storage_engine=InnoDB&useUnicode=true&characterEncoding=UTF-8

Hope that helps…

raff · June 3, 2015, 11:28am

Could you please try setting auto_update_database=false in openmrs-runtime.properties? It may be possible that auto update is triggered too late.

By the way thanks for providing all those details to troubleshoot the issue!

mario · June 3, 2015, 1:17pm

It was the auto_update_database setting. Setting it to “false” would start the server and then direct me to the wizzard page. Continuing from there the liquibase changes are applied and the db looks good.

Should I create an issue for that?

raff · June 3, 2015, 1:18pm

Yes, please create an issue and link it here! Thanks!

mario · June 3, 2015, 1:44pm

The related issue in JIRA can be found here:

dkayiwa · August 4, 2015, 2:57pm

http://int01.openmrs.org:8080/openmrs is facing the same problem. Can you remind me about the scenarios where one would need to set auto_update_database=true Our current code just assumes that the database is up to date whenever this value is set to true, and hence these errors. What should it do in such cases?

raff · August 5, 2015, 7:13am

I could imagine an administrator having to roll out a new war to multiple servers and not having to login to each of them to perform database update does save some time. Any automated deployment also benefits from not having to go to the web browser to run the upgrade.