DatabaseUpdateException when starting OpenMRS after restore from backup: what's going on?

Application Name: OpenMRS Platform Version Number: Version: 1.10.2 Build 64d903 (Last Build: 2015-05-21 13:42)

Question:

On Friday I was getting an exception when OpenMRS tries to start up after restoring from a database back up.

This is what I did:

  1. Ran the Buendia installation script which installed OpenMRS and initiated it with the base database for Project Buendia
  2. Added a patient
  3. Backed up the database using the openmrs_dump script, which does a mysqldump
  4. Restored from that back up using the openmrs_load script, which drops the database, creates a new database and runs the sql from the dump
  5. Browsed to http://server:9000/openmrs where usually the log in page would come up

It redirected to http://server:9000/openmrs/initialsetup with the error message below:

The following error occurred at startup: Unable to start OpenMRS. Error thrown was: Should not be here because updates were run previously org.openmrs.module.ModuleException: Unable to start OpenMRS. Error thrown was: Should not be here because updates were run previously at org.openmrs.web.WebDaemon.startOpenmrs(WebDaemon.java:64) at org.openmrs.web.Listener.contextInitialized(Listener.java:145) at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:4790) at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5284) at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150) at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:899) at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:875) at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:618) at org.apache.catalina.startup.HostConfig.deployWAR(HostConfig.java:963) at org.apache.catalina.startup.HostConfig$DeployWar.run(HostConfig.java:1600) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334) at java.util.concurrent.FutureTask.run(FutureTask.java:166) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) at java.lang.Thread.run(Thread.java:722) Caused by: javax.servlet.ServletException: Should not be here because updates were run previously at org.openmrs.web.Listener.startOpenmrs(Listener.java:194) at org.openmrs.web.WebDaemon$1.run(WebDaemon.java:42) Caused by: org.openmrs.util.DatabaseUpdateException: There was an error while updating the database to the latest. file: liquibase-update-to-latest.xml. Error: liquibase.exception.DatabaseException: Empty result set, expected one row at org.openmrs.util.DatabaseUpdater.executeChangelog(DatabaseUpdater.java:151) at org.openmrs.util.DatabaseUpdater.executeChangelog(DatabaseUpdater.java:111) at org.openmrs.util.DatabaseUpdater.executeChangelog(DatabaseUpdater.java:94) at org.openmrs.api.context.Context.checkForDatabaseUpdates(Context.java:1112) at org.openmrs.api.context.Context.startup(Context.java:823) at org.openmrs.web.Listener.startOpenmrs(Listener.java:191) … 1 more Caused by: liquibase.exception.LockException: liquibase.exception.DatabaseException: Empty result set, expected one row at liquibase.lockservice.LockService.acquireLock(LockService.java:121) at liquibase.lockservice.LockService.waitForLock(LockService.java:61) at org.openmrs.util.DatabaseUpdater.executeChangelog(DatabaseUpdater.java:215) at org.openmrs.util.DatabaseUpdater.executeChangelog(DatabaseUpdater.java:163) at org.openmrs.util.DatabaseUpdater.executeChangelog(DatabaseUpdater.java:148) … 6 more Caused by: liquibase.exception.DatabaseException: Empty result set, expected one row at liquibase.util.JdbcUtils.requiredSingleResult(JdbcUtils.java:124) at liquibase.executor.jvm.JdbcExecutor.queryForObject(JdbcExecutor.java:159) at liquibase.executor.jvm.JdbcExecutor.queryForObject(JdbcExecutor.java:167) at liquibase.executor.jvm.JdbcExecutor.queryForObject(JdbcExecutor.java:163) at liquibase.lockservice.LockService.acquireLock(LockService.java:96) … 10 more See the server log for full output.

2 days later, without having done anything except restart the server, it is now working.

Can anyone shed any light or give me any clues as to why this might have happened?

It’s important to us to have an hourly back up working and be able to restore from that back up as we’ll be holding critical patient information in the database.

What does it mean “Should not be here because updates were run previously”?

What is DatabaseUpdater.java for? What is it expected to do?

If I go to http://server:9000/openmrs/admin/maintenance/databaseChangesInfo.list I do see that most of the updates are from November 2014, but there are two updates from the day that I did the restore (22 Jan 2016):

22-Jan-2016 Removing invalid foreign key constraint from order_type.parent column to order.order_id column Drop Foreign Key Constraint ALREADY_RAN mseaton 22-Jan-2016 Adding foreign key constraint from order_type.parent column to order_type.order_type_id column Add Foreign Key Constraint ALREADY_RAN mseaton

I need to solve this within the next few days as we are deploying for a major field trial next week, so any help or guidance would be really appreciated. Thanks!

1 Like

The times i have seen this kind of behaviour is when one is restoring on a different version of openmrs than that of the backup. The two changesets you have listed were added in 1.10.2. So the backup was either for 1.10.0 or 1.10.1

On another note, we used to have some liquibase changelog lock bugs in older versions of openmrs. Do you have any particular reason why you are not running 1.11?

Thanks @dkayiwa!

I solved it!

Turns out we had a watchdog process that was set up to automatically restart tomcat if it was down, checking every 5 minutes. This was often happening while the restore script was running so part way through restoring the MySql database.

So I think the problem was related to OpenMRS trying to start up with only a partial database, and I’m not sure if it also meant two instances of Tomcat running, which I imagine would cause problems too.

Solution was to check in our watchdog script to not attempt to start tomcat if the restore script is running.

I figured this out by looking at the catalina.out log file from Tomcat in /var/log/tomcat7

HAPPY!! :slightly_smiling:

Thank you so much @danc for sharing with us how you fixed it. This is very useful feedback for our troubleshooting knowledge base! :smile:

1 Like

Am facing the same problem on windows running tomcat 7. I thought openmrs was capable of automatically creating a new database if the existing on was removed. I dropped the database and redeployed tomcat. But I keep getting the same error as stated by @danc above. I have no clue on how to approach this. I even replaced my tomcat and redeployed openmrs, but still.

https://pastebin.com/XGdNJijr

Can you paste this stack trace at pastebin.com? The here you just include a link to it.

great, doing that now.

https://pastebin.com/XGdNJijr

Now edit your previous post by removing the stack trace and replace it with this link.

@dkayiwa I have edited my post. Thanks for the tips.

If you want a fresh setup, after dropping the database, you also need to delete the runtime properties file. https://wiki.openmrs.org/display/docs/Overriding+OpenMRS+Default+Runtime+Properties

great, it worked thanks @dkayiwa