MySQL 8.0 Docker could not create connection to database server

cioan · February 12, 2025, 9:34pm

Has anyone seen this jdbc connection problem with some of the OpenMRS modules?

My environment is Mac M2, MySQL 8.0 Docker container, Java version: 1.8.0_431, openmrs-sdk Version: 6.1.0 OpenMRS core starts fine along with a few modules(fhir2-2.3.0-SNAPSHOT, legacyui-1.22.0, spa-2.1.0-SNAPSHOT, webservices.rest-2.46). The O3 dev environment runs fine. But when I try to add other modules that we use in PIH EMR, the following errors are thrown by some modules. One module that consistently fails to run the liquibase is the addresshierarchy-2.20.0-SNAPSHOT module:

INFO - Slf4JLogger.log(43) |2025-02-12T15:12:55,690| Successfully released change log lock
WARN - ModuleFactory.startModuleInternal(783) |2025-02-12T15:12:59,839| Error while trying to start module: openconceptlab
org.openmrs.module.ModuleException: Unable to update data model using liquibase.xml. Module: Open Concept Lab Module
	at org.openmrs.module.ModuleFactory.runLiquibase(ModuleFactory.java:1002) ~[openmrs-api-2.6.15-SNAPSHOT.jar:?]
	at org.openmrs.module.ModuleFactory.startModuleInternal(ModuleFactory.java:723) ~[openmrs-api-2.6.15-SNAPSHOT.jar:?]
	at org.openmrs.api.context.Daemon$1.run(Daemon.java:86) ~[openmrs-api-2.6.15-SNAPSHOT.jar:?]
Caused by: java.lang.Exception: Unable to get a connection to the database.  Please check your openmrs runtime properties file and make sure you have the correct connection.username and connection.password set
	at org.openmrs.util.DatabaseUpdater.getLiquibase(DatabaseUpdater.java:402) ~[openmrs-api-2.6.15-SNAPSHOT.jar:?]
	at org.openmrs.util.DatabaseUpdater.executeChangelog(DatabaseUpdater.java:215) ~[openmrs-api-2.6.15-SNAPSHOT.jar:?]
	at org.openmrs.module.ModuleFactory.runLiquibase(ModuleFactory.java:994) ~[openmrs-api-2.6.15-SNAPSHOT.jar:?]
	... 2 more
Caused by: java.sql.SQLNonTransientConnectionException: Could not create connection to database server. Attempted reconnect 3 times. Giving up.
	at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:110) ~[mysql-connector-java-8.0.30.jar:8.0.30]
	at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:97) ~[mysql-connector-java-8.0.30.jar:8.0.30]
	at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:89) ~[mysql-connector-java-8.0.30.jar:8.0.30]
	at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:63) ~[mysql-connector-java-8.0.30.jar:8.0.30]
	at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:73) ~[mysql-connector-java-8.0.30.jar:8.0.30]
	at com.mysql.cj.jdbc.ConnectionImpl.connectWithRetries(ConnectionImpl.java:898) ~[mysql-connector-java-8.0.30.jar:8.0.30]
	at com.mysql.cj.jdbc.ConnectionImpl.createNewIO(ConnectionImpl.java:823) ~[mysql-connector-java-8.0.30.jar:8.0.30]
	at com.mysql.cj.jdbc.ConnectionImpl.<init>(ConnectionImpl.java:448) ~[mysql-connector-java-8.0.30.jar:8.0.30]
	at com.mysql.cj.jdbc.ConnectionImpl.getInstance(ConnectionImpl.java:241) ~[mysql-connector-java-8.0.30.jar:8.0.30]
	at com.mysql.cj.jdbc.NonRegisteringDriver.connect(NonRegisteringDriver.java:198) ~[mysql-connector-java-8.0.30.jar:8.0.30]
	at java.sql.DriverManager.getConnection(DriverManager.java:664) ~[?:1.8.0_431]
	at java.sql.DriverManager.getConnection(DriverManager.java:247) ~[?:1.8.0_431]
	at org.openmrs.util.DatabaseUpdater.getConnection(DatabaseUpdater.java:461) ~[openmrs-api-2.6.15-SNAPSHOT.jar:?]
	at org.openmrs.util.DatabaseUpdater.getLiquibase(DatabaseUpdater.java:399) ~[openmrs-api-2.6.15-SNAPSHOT.jar:?]
	at org.openmrs.util.DatabaseUpdater.executeChangelog(DatabaseUpdater.java:215) ~[openmrs-api-2.6.15-SNAPSHOT.jar:?]
	at org.openmrs.module.ModuleFactory.runLiquibase(ModuleFactory.java:994) ~[openmrs-api-2.6.15-SNAPSHOT.jar:?]
	... 2 more
Caused by: com.mysql.cj.exceptions.CJCommunicationsException: Communications link failure

my db connection URL is the following:

connection.url=jdbc\:mysql\://127.0.0.1\:3308/openmrs?autoReconnect\=true&useUnicode\=true&characterEncoding\=UTF-8&sessionVariables\=default_storage_engine%3DInnoDB&serverTimezone\=US/Eastern

and I could connect fine to the MySQL docker container from the command line.

Thanks for any suggestions on how to go about debugging this connection problem.

cioan · February 13, 2025, 2:11pm

If I add just the addresshierarchy module then the OpenMRS SDK environment starts fine:

So, I guess the problem is not with a particular module, but rather with the number of modules that are part of a distribution? Maybe the DB connection is not properly closed and after a certain number of connection MySQL refuses any new connections? Any other suggestions?

ibacher · February 13, 2025, 2:24pm

Usually, the communications link failure is some low-level network issue connecting to the DB. It’s be weird if adding a module somehow broke that.

Are you adding modules via the UI?

ibacher · February 13, 2025, 2:26pm

MySQL does have a maximum number of connections, but usually you’d see a “Too many connections” error if that happens.

cioan · February 13, 2025, 2:35pm

Thanks @ibacher ! I am adding the modules by copying them into the OpenMRS SDK instance modules directory, and then restarting the SDK.

cioan · February 13, 2025, 2:42pm

I am making “progress”, I am up to 12, the number of modules that successfully started:

dkayiwa · February 13, 2025, 6:33pm

Is this something easy to reproduce by anyone else?

cioan · February 14, 2025, 1:08pm

Good question, @dkayiwa ! It would be good to know if anyone else developing on Mac M2 had any problems connecting OpenMRS to MySQL 8. I am able to get the reference app, and O3 running just fine, but when the number of modules is much higher (PIH EMR has 52 modules) then I start getting those type of “Communication link failure” . I am curious if other developers working with large number of modules had similar issues?

dkayiwa · February 14, 2025, 1:23pm

What are the instructions for setting that up locally?

cioan · February 14, 2025, 1:39pm

@dkayiwa , the instructions for setting up PIH EMR development environment are here GitHub - PIH/openmrs-distro-pihemr: Custom EMR application for Mirebalais Hospital . They are a bit complicated. @mseaton who is developing on Ubuntu was able to get his PIH EMR dev environment to work with MySQL 8. So, I don’t think it is an OpenMRS issue, but rather some environment configuration with my machine, which I still have not figured out.

ibacher · February 14, 2025, 1:40pm

@cioan Isn’t the O2 RefApp roughly the same order of size (43 modules) as the PIH EMR?

cioan · February 14, 2025, 1:41pm

I have not tried setting up O2 RefApp. I will try that. Thanks @ibacher !

ibacher · February 14, 2025, 1:42pm

Ok. That’s what I was going to use to try locally. I’ve got an M3 rather than M2, but that shouldn’t really matter.

ibacher · February 14, 2025, 2:10pm

Hmmm… RefApp 2.13.0 runs correctly for me (installed using SDK). I’ll see if I can replicate with Mirebalais setup.

cioan · February 14, 2025, 2:15pm

Thanks @ibacher ! I was able to get the RefApp 2.14 running correctly too. That’s encouraging. Don’t worry about setting up Mirebalais app. Let me try first, to reinstall PIH EMR using the same Docker container that I had for O2 RefApp but with a new database. I will let you know. Thanks!

cioan · February 14, 2025, 3:41pm

I have tried to setup the Mirebalais instance with an empty db, but I got the same type of errors:

INFO - Slf4JLogger.log(43) |2025-02-14T10:36:10,722| Reading from mirebalais.liquibasechangelog
INFO - Slf4JLogger.log(43) |2025-02-14T10:36:10,749| Successfully acquired change log lock
INFO - Slf4JLogger.log(43) |2025-02-14T10:36:10,753| Successfully released change log lock
WARN - ModuleFactory.startModuleInternal(783) |2025-02-14T10:36:14,817| Error while trying to start module: namephonetics
org.openmrs.module.ModuleException: Unable to update data model using liquibase.xml. Module: Name Phonetics
	at org.openmrs.module.ModuleFactory.runLiquibase(ModuleFactory.java:1002) ~[openmrs-api-2.6.15.jar:?]
	at org.openmrs.module.ModuleFactory.startModuleInternal(ModuleFactory.java:723) ~[openmrs-api-2.6.15.jar:?]
	at org.openmrs.api.context.Daemon$1.run(Daemon.java:86) ~[openmrs-api-2.6.15.jar:?]
Caused by: java.lang.Exception: Unable to get a connection to the database.  Please check your openmrs runtime properties file and make sure you have the correct connection.username and connection.password set
	at org.openmrs.util.DatabaseUpdater.getLiquibase(DatabaseUpdater.java:402) ~[openmrs-api-2.6.15.jar:?]
	at org.openmrs.util.DatabaseUpdater.executeChangelog(DatabaseUpdater.java:215) ~[openmrs-api-2.6.15.jar:?]
	at org.openmrs.module.ModuleFactory.runLiquibase(ModuleFactory.java:994) ~[openmrs-api-2.6.15.jar:?]
	... 2 more
Caused by: java.sql.SQLNonTransientConnectionException: Could not create connection to database server. Attempted reconnect 3 times. Giving up.
	at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:110) ~[mysql-connector-java-8.0.30.jar:8.0.30]
	at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:97) ~[mysql-connector-java-8.0.30.jar:8.0.30]
	at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:89) ~[mysql-connector-java-8.0.30.jar:8.0.30]
	at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:63) ~[mysql-connector-java-8.0.30.jar:8.0.30]
	at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:73) ~[mysql-connector-java-8.0.30.jar:8.0.30]
	at com.mysql.cj.jdbc.ConnectionImpl.connectWithRetries(ConnectionImpl.java:898) ~[mysql-connector-java-8.0.30.jar:8.0.30]
	at com.mysql.cj.jdbc.ConnectionImpl.createNewIO(ConnectionImpl.java:823) ~[mysql-connector-java-8.0.30.jar:8.0.30]
	at com.mysql.cj.jdbc.ConnectionImpl.<init>(ConnectionImpl.java:448) ~[mysql-connector-java-8.0.30.jar:8.0.30]
	at com.mysql.cj.jdbc.ConnectionImpl.getInstance(ConnectionImpl.java:241) ~[mysql-connector-java-8.0.30.jar:8.0.30]
	at com.mysql.cj.jdbc.NonRegisteringDriver.connect(NonRegisteringDriver.java:198) ~[mysql-connector-java-8.0.30.jar:8.0.30]
	at java.sql.DriverManager.getConnection(DriverManager.java:664) ~[?:1.8.0_431]
	at java.sql.DriverManager.getConnection(DriverManager.java:247) ~[?:1.8.0_431]
	at org.openmrs.util.DatabaseUpdater.getConnection(DatabaseUpdater.java:461) ~[openmrs-api-2.6.15.jar:?]
	at org.openmrs.util.DatabaseUpdater.getLiquibase(DatabaseUpdater.java:399) ~[openmrs-api-2.6.15.jar:?]
	at org.openmrs.util.DatabaseUpdater.executeChangelog(DatabaseUpdater.java:215) ~[openmrs-api-2.6.15.jar:?]
	at org.openmrs.module.ModuleFactory.runLiquibase(ModuleFactory.java:994) ~[openmrs-api-2.6.15.jar:?]
	... 2 more
Caused by: com.mysql.cj.exceptions.CJCommunicationsException: Communications link failure

The last packet sent successfully to the server was 0 milliseconds ago. The driver has not received any packets from the server.
	at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) ~[?:1.8.0_431]
	at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62) ~[?:1.8.0_431]
	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[?:1.8.0_431]
	at java.lang.reflect.Constructor.newInstance(Constructor.java:423) ~[?:1.8.0_431]
	at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:61) ~[mysql-connector-java-8.0.30.jar:8.0.30]
	at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:105) ~[mysql-connector-java-8.0.30.jar:8.0.30]
	at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:151) ~[mysql-connector-java-8.0.30.jar:8.0.30]
	at com.mysql.cj.exceptions.ExceptionFactory.createCommunicationsException(ExceptionFactory.java:167) ~[mysql-connector-java-8.0.30.jar:8.0.30]
	at com.mysql.cj.protocol.a.NativeSocketConnection.connect(NativeSocketConnection.java:89) ~[mysql-connector-java-8.0.30.jar:8.0.30]
	at com.mysql.cj.NativeSession.connect(NativeSession.java:120) ~[mysql-connector-java-8.0.30.jar:8.0.30]
	at com.mysql.cj.jdbc.ConnectionImpl.connectWithRetries(ConnectionImpl.java:842) ~[mysql-connector-java-8.0.30.jar:8.0.30]
	at com.mysql.cj.jdbc.ConnectionImpl.createNewIO(ConnectionImpl.java:823) ~[mysql-connector-java-8.0.30.jar:8.0.30]
	at com.mysql.cj.jdbc.ConnectionImpl.<init>(ConnectionImpl.java:448) ~[mysql-connector-java-8.0.30.jar:8.0.30]
	at com.mysql.cj.jdbc.ConnectionImpl.getInstance(ConnectionImpl.java:241) ~[mysql-connector-java-8.0.30.jar:8.0.30]
	at com.mysql.cj.jdbc.NonRegisteringDriver.connect(NonRegisteringDriver.java:198) ~[mysql-connector-java-8.0.30.jar:8.0.30]
	at java.sql.DriverManager.getConnection(DriverManager.java:664) ~[?:1.8.0_431]
	at java.sql.DriverManager.getConnection(DriverManager.java:247) ~[?:1.8.0_431]
	at org.openmrs.util.DatabaseUpdater.getConnection(DatabaseUpdater.java:461) ~[openmrs-api-2.6.15.jar:?]
	at org.openmrs.util.DatabaseUpdater.getLiquibase(DatabaseUpdater.java:399) ~[openmrs-api-2.6.15.jar:?]
	at org.openmrs.util.DatabaseUpdater.executeChangelog(DatabaseUpdater.java:215) ~[openmrs-api-2.6.15.jar:?]
	at org.openmrs.module.ModuleFactory.runLiquibase(ModuleFactory.java:994) ~[openmrs-api-2.6.15.jar:?]
	... 2 more
Caused by: java.net.SocketException: Socket closed
	at java.net.PlainSocketImpl.socketConnect(Native Method) ~[?:1.8.0_431]
	at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:476) ~[?:1.8.0_431]
	at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:218) ~[?:1.8.0_431]
	at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:200) ~[?:1.8.0_431]
	at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:394) ~[?:1.8.0_431]
	at java.net.Socket.connect(Socket.java:606) ~[?:1.8.0_431]
	at com.mysql.cj.protocol.StandardSocketFactory.connect(StandardSocketFactory.java:153) ~[mysql-connector-java-8.0.30.jar:8.0.30]
	at com.mysql.cj.protocol.a.NativeSocketConnection.connect(NativeSocketConnection.java:63) ~[mysql-connector-java-8.0.30.jar:8.0.30]
	at com.mysql.cj.NativeSession.connect(NativeSession.java:120) ~[mysql-connector-java-8.0.30.jar:8.0.30]
	at com.mysql.cj.jdbc.ConnectionImpl.connectWithRetries(ConnectionImpl.java:842) ~[mysql-connector-java-8.0.30.jar:8.0.30]
	at com.mysql.cj.jdbc.ConnectionImpl.createNewIO(ConnectionImpl.java:823) ~[mysql-connector-java-8.0.30.jar:8.0.30]
	at com.mysql.cj.jdbc.ConnectionImpl.<init>(ConnectionImpl.java:448) ~[mysql-connector-java-8.0.30.jar:8.0.30]
	at com.mysql.cj.jdbc.ConnectionImpl.getInstance(ConnectionImpl.java:241) ~[mysql-connector-java-8.0.30.jar:8.0.30]
	at com.mysql.cj.jdbc.NonRegisteringDriver.connect(NonRegisteringDriver.java:198) ~[mysql-connector-java-8.0.30.jar:8.0.30]
	at java.sql.DriverManager.getConnection(DriverManager.java:664) ~[?:1.8.0_431]
	at java.sql.DriverManager.getConnection(DriverManager.java:247) ~[?:1.8.0_431]
	at org.openmrs.util.DatabaseUpdater.getConnection(DatabaseUpdater.java:461) ~[openmrs-api-2.6.15.jar:?]
	at org.openmrs.util.DatabaseUpdater.getLiquibase(DatabaseUpdater.java:399) ~[openmrs-api-2.6.15.jar:?]
	at org.openmrs.util.DatabaseUpdater.executeChangelog(DatabaseUpdater.java:215) ~[openmrs-api-2.6.15.jar:?]
	at org.openmrs.module.ModuleFactory.runLiquibase(ModuleFactory.java:994) ~[openmrs-api-2.6.15.jar:?]
	... 2 more

ibacher · February 14, 2025, 6:46pm

That’s unfortunate. It does seem like connection exhaustion in the DatabaseUpdater is possible; we’re bypassing C3P0 there to create connections and I’m not altogether convinced we always close them property.

@cioan What’s the output if you run SHOW PROCESSLIST on the MySQL database while OpenMRS is starting?

cioan · February 17, 2025, 5:40pm

@ibacher , I think that your suspicions are on the right track. I have noticed too that when I start getting those connection errors, the following line of code is failing:

github.com/openmrs/openmrs-core

api/src/main/java/org/openmrs/util/DatabaseUpdater.java

2.6.x


      
          				if (lockHandler != null) {
          					lockHandler.releaseLock();
          				}
          			}
          			catch (Exception e) {
          				log.error("Could not release lock", e);
          			}
          
          			try {
          				if (database != null && database.getConnection() != null) {
          					database.getConnection().close();
          				}
          			}
          			catch (Exception e) {
          				//pass
          			}
          		}
          		
          		return updateWarnings;
          	}

and unfortunately we don’t do anything with this failure:

github.com/openmrs/openmrs-core

api/src/main/java/org/openmrs/util/DatabaseUpdater.java

2.6.x


      
          			catch (Exception e) {
          				log.error("Could not release lock", e);
          			}
          
          			try {
          				if (database != null && database.getConnection() != null) {
          					database.getConnection().close();
          				}
          			}
          			catch (Exception e) {
          				//pass
          			}
          		}
          		
          		return updateWarnings;
          	}
          	
          	/**
          	 * Ask Liquibase if it needs to do any updates.
          	 *
          	 * @return true/false whether database updates are required

This sounds a little crazy, but I step through each module startup liquibase update, and I think just because I had a breaking point at the database close connection line that gave enough time to the connection to actually close. I also monitored mysql processes as you indicated:

mysql> show processlist;
+-----+-----------------+------------------+-------+---------+------+------------------------+------------------+
| Id  | User            | Host             | db    | Command | Time | State                  | Info             |
+-----+-----------------+------------------+-------+---------+------+------------------------+------------------+
|   5 | event_scheduler | localhost        | NULL  | Daemon  | 6308 | Waiting on empty queue | NULL             |
|   9 | root            | 172.17.0.1:62180 | haiti | Query   |    0 | init                   | show processlist |
| 148 | root            | 172.17.0.1:64150 | haiti | Sleep   |   15 |                        | NULL             |
| 149 | root            | 172.17.0.1:63642 | haiti | Sleep   |   60 |                        | NULL             |
| 156 | root            | 172.17.0.1:57864 | haiti | Sleep   |    6 |                        | NULL             |
+-----+-----------------+------------------+-------+---------+------+------------------------+------------------+
5 rows in set, 1 warning (0.00 sec)

mysql> show processlist;
+-----+-----------------+------------------+-------+---------+------+------------------------+------------------+
| Id  | User            | Host             | db    | Command | Time | State                  | Info             |
+-----+-----------------+------------------+-------+---------+------+------------------------+------------------+
|   5 | event_scheduler | localhost        | NULL  | Daemon  | 6316 | Waiting on empty queue | NULL             |
|   9 | root            | 172.17.0.1:62180 | haiti | Query   |    0 | init                   | show processlist |
| 148 | root            | 172.17.0.1:64150 | haiti | Sleep   |    2 |                        | NULL             |
| 149 | root            | 172.17.0.1:63642 | haiti | Sleep   |    2 |                        | NULL             |
+-----+-----------------+------------------+-------+---------+------+------------------------+------------------+
4 rows in set, 1 warning (0.00 sec)

mysql> show processlist;
+-----+-----------------+------------------+-------+---------+------+------------------------+------------------+
| Id  | User            | Host             | db    | Command | Time | State                  | Info             |
+-----+-----------------+------------------+-------+---------+------+------------------------+------------------+
|   5 | event_scheduler | localhost        | NULL  | Daemon  | 6436 | Waiting on empty queue | NULL             |
|   9 | root            | 172.17.0.1:62180 | haiti | Query   |    0 | init                   | show processlist |
| 148 | root            | 172.17.0.1:64150 | haiti | Sleep   |    8 |                        | NULL             |
| 149 | root            | 172.17.0.1:63642 | haiti | Sleep   |    8 |                        | NULL             |
| 168 | root            | 172.17.0.1:62338 | haiti | Sleep   |    5 |                        | NULL             |
+-----+-----------------+------------------+-------+---------+------+------------------------+------------------+
5 rows in set, 1 warning (0.01 sec)

mysql> show processlist;
+-----+-----------------+------------------+-------+---------+------+------------------------+------------------+
| Id  | User            | Host             | db    | Command | Time | State                  | Info             |
+-----+-----------------+------------------+-------+---------+------+------------------------+------------------+
|   5 | event_scheduler | localhost        | NULL  | Daemon  | 6615 | Waiting on empty queue | NULL             |
|   9 | root            | 172.17.0.1:62180 | haiti | Query   |    0 | init                   | show processlist |
| 148 | root            | 172.17.0.1:64150 | haiti | Sleep   |   21 |                        | NULL             |
| 149 | root            | 172.17.0.1:63642 | haiti | Sleep   |   18 |                        | NULL             |
| 192 | root            | 172.17.0.1:59570 | haiti | Sleep   |   16 |                        | NULL             |
+-----+-----------------+------------------+-------+---------+------+------------------------+------------------+
5 rows in set, 1 warning (0.00 sec)

mysql> show processlist;
+-----+-----------------+------------------+-------+---------+------+------------------------+------------------+
| Id  | User            | Host             | db    | Command | Time | State                  | Info             |
+-----+-----------------+------------------+-------+---------+------+------------------------+------------------+
|   5 | event_scheduler | localhost        | NULL  | Daemon  | 6660 | Waiting on empty queue | NULL             |
|   9 | root            | 172.17.0.1:62180 | haiti | Query   |    0 | init                   | show processlist |
| 193 | root            | 172.17.0.1:63918 | haiti | Sleep   |    2 |                        | NULL             |
+-----+-----------------+------------------+-------+---------+------+------------------------+------------------+
3 rows in set, 1 warning (0.01 sec)

mysql> show processlist;
+-----+-----------------+------------------+-------+---------+------+------------------------+------------------+
| Id  | User            | Host             | db    | Command | Time | State                  | Info             |
+-----+-----------------+------------------+-------+---------+------+------------------------+------------------+
|   5 | event_scheduler | localhost        | NULL  | Daemon  | 6862 | Waiting on empty queue | NULL             |
|   9 | root            | 172.17.0.1:62180 | haiti | Query   |    0 | init                   | show processlist |
| 193 | root            | 172.17.0.1:63918 | haiti | Sleep   |   76 |                        | NULL             |
| 195 | root            | 172.17.0.1:57530 | haiti | Sleep   |   16 |                        | NULL             |
| 196 | root            | 172.17.0.1:62500 | haiti | Sleep   |   17 |                        | NULL             |
| 197 | root            | 172.17.0.1:62514 | haiti | Sleep   |   75 |                        | NULL             |
| 198 | root            | 172.17.0.1:56456 | haiti | Sleep   |   15 |                        | NULL             |
+-----+-----------------+------------------+-------+---------+------+------------------------+------------------+
7 rows in set, 1 warning (0.00 sec)

So, finally it looks like most of the modules started and ran their liquibase updates. Now I am getting real SQL errors, which I could debug and fix. These are related to our PIH liquibase updates:

INFO - Slf4JLogger.log(43) |2025-02-17T12:22:02,546| Custom SQL executed
INFO - Slf4JLogger.log(43) |2025-02-17T12:22:02,547| ChangeSet configuration/pih/liquibase/liquibase.xml::20210602-delete-unused-ces-programs::jmbabazi ran successfully in 4ms
INFO - Slf4JLogger.log(43) |2025-02-17T12:22:02,555| Custom SQL executed
INFO - Slf4JLogger.log(43) |2025-02-17T12:22:02,556| ChangeSet configuration/pih/liquibase/liquibase.xml::20210608-migrate-anc-v1-to-obgyn-encounters::ball ran successfully in 5ms
INFO - Slf4JLogger.log(43) |2025-02-17T12:22:02,561| Marking ChangeSet: configuration/pih/liquibase/liquibase.xml::20210701-migrate-mentalhealth-drug-to-other::ball ran despite precondition failure due to onFail='MARK_RAN': 
          configuration/pih/liquibase/liquibase.xml : SQL Precondition failed.  Expected '1' got '0'

INFO - Slf4JLogger.log(43) |2025-02-17T12:22:02,570| Successfully released change log lock
ERROR - LiquibaseSetup.setup(31) |2025-02-17T12:23:51,207| Unable run liquibase change sets provided by PIH EMR config
org.openmrs.util.DatabaseUpdateException: There was an error while updating the database to the latest. file: configuration/pih/liquibase/liquibase.xml. Error: liquibase.exception.LiquibaseException: Unable to execute change set: configuration/pih/liquibase/liquibase.xml::20210726-migrate-c-section-risk-factor::ball
	at org.openmrs.util.DatabaseUpdater.executeChangelog(DatabaseUpdater.java:192) ~[openmrs-api-2.6.15.jar:?]
	at org.openmrs.module.pihcore.setup.LiquibaseSetup.setup(LiquibaseSetup.java:25) ~[pihcore-api-2.0.0-SNAPSHOT.jar:?]
	at org.openmrs.module.pihcore.setup.ConfigurationSetup.configureDependencies(ConfigurationSetup.java:170) ~[pihcore.jar:?]
	at org.openmrs.module.pihcore.PihCoreActivator.configureSystem(PihCoreActivator.java:51) ~[pihcore.jar:?]
	at org.openmrs.module.pihcore.PihCoreActivator.started(PihCoreActivator.java:41) ~[pihcore.jar:?]
	at org.openmrs.module.ModuleUtil.refreshApplicationContext(ModuleUtil.java:922) ~[openmrs-api-2.6.15.jar:?]
	at org.openmrs.module.web.WebModuleUtil.refreshWAC(WebModuleUtil.java:923) ~[openmrs-web-2.6.15.jar:?]
	at org.openmrs.web.Listener.performWebStartOfModules(Listener.java:723) ~[openmrs-web-2.6.15.jar:?]
	at org.openmrs.web.Listener.performWebStartOfModules(Listener.java:703) ~[openmrs-web-2.6.15.jar:?]
	at org.openmrs.web.Listener.startOpenmrs(Listener.java:369) ~[openmrs-web-2.6.15.jar:?]
	at org.openmrs.web.WebDaemon$1.run(WebDaemon.java:42) ~[openmrs-web-2.6.15.jar:?]
Caused by: liquibase.exception.LiquibaseException: liquibase.exception.LiquibaseException: Unable to execute change set: configuration/pih/liquibase/liquibase.xml::20210726-migrate-c-section-risk-factor::ball
	at liquibase.changelog.ChangeLogIterator.run(ChangeLogIterator.java:124) ~[liquibase-core-4.4.3.jar:?]
	at org.openmrs.util.DatabaseUpdater.executeChangelog(DatabaseUpdater.java:237) ~[openmrs-api-2.6.15.jar:?]
	at org.openmrs.util.DatabaseUpdater.executeChangelog(DatabaseUpdater.java:188) ~[openmrs-api-2.6.15.jar:?]
	... 10 more
Caused by: liquibase.exception.LiquibaseException: Unable to execute change set: configuration/pih/liquibase/liquibase.xml::20210726-migrate-c-section-risk-factor::ball
	at org.openmrs.util.DatabaseUpdater$OpenmrsUpdateVisitor.visit(DatabaseUpdater.java:864) ~[openmrs-api-2.6.15.jar:?]
	at liquibase.changelog.ChangeLogIterator$2.lambda$null$0(ChangeLogIterator.java:111) ~[liquibase-core-4.4.3.jar:?]
	at liquibase.Scope.lambda$child$0(Scope.java:166) ~[liquibase-core-4.4.3.jar:?]
	at liquibase.Scope.child(Scope.java:175) ~[liquibase-core-4.4.3.jar:?]
	at liquibase.Scope.child(Scope.java:165) ~[liquibase-core-4.4.3.jar:?]
	at liquibase.Scope.child(Scope.java:144) ~[liquibase-core-4.4.3.jar:?]
	at liquibase.changelog.ChangeLogIterator$2.lambda$run$1(ChangeLogIterator.java:110) ~[liquibase-core-4.4.3.jar:?]
	at liquibase.Scope.lambda$child$0(Scope.java:166) ~[liquibase-core-4.4.3.jar:?]
	at liquibase.Scope.child(Scope.java:175) ~[liquibase-core-4.4.3.jar:?]
	at liquibase.Scope.child(Scope.java:165) ~[liquibase-core-4.4.3.jar:?]
	at liquibase.Scope.child(Scope.java:144) ~[liquibase-core-4.4.3.jar:?]
	at liquibase.Scope.child(Scope.java:228) ~[liquibase-core-4.4.3.jar:?]
	at liquibase.changelog.ChangeLogIterator$2.run(ChangeLogIterator.java:94) ~[liquibase-core-4.4.3.jar:?]
	at liquibase.Scope.lambda$child$0(Scope.java:166) ~[liquibase-core-4.4.3.jar:?]
	at liquibase.Scope.child(Scope.java:175) ~[liquibase-core-4.4.3.jar:?]
	at liquibase.Scope.child(Scope.java:165) ~[liquibase-core-4.4.3.jar:?]
	at liquibase.Scope.child(Scope.java:144) ~[liquibase-core-4.4.3.jar:?]
	at liquibase.Scope.child(Scope.java:228) ~[liquibase-core-4.4.3.jar:?]
	at liquibase.Scope.child(Scope.java:232) ~[liquibase-core-4.4.3.jar:?]
	at liquibase.changelog.ChangeLogIterator.run(ChangeLogIterator.java:66) ~[liquibase-core-4.4.3.jar:?]
	at org.openmrs.util.DatabaseUpdater.executeChangelog(DatabaseUpdater.java:237) ~[openmrs-api-2.6.15.jar:?]
	at org.openmrs.util.DatabaseUpdater.executeChangelog(DatabaseUpdater.java:188) ~[openmrs-api-2.6.15.jar:?]
	... 10 more
Caused by: liquibase.exception.MigrationFailedException: Migration failed for change set configuration/pih/liquibase/liquibase.xml::20210726-migrate-c-section-risk-factor::ball:
     Reason: liquibase.exception.DatabaseException: You can't specify target table 'obs' for update in FROM clause [Failed SQL: (1093) update obs,
                   (select encounter_id from encounter
                     where encounter_type IN
                            (select encounter_type_id from encounter_type
                              where name like 'OB%GYN')
                      and encounter_id NOT IN
                            (select encounter_id from obs
                              where voided = 0
                                and concept_id =
                                    (select concept_id from concept
                                      where uuid like '160079AAAAAAAAAAAAAAAAAAAAAAAAAAAAAA')
                                and value_coded =
                                    (select concept_id from concept
                                      where uuid like '123450AAAAAAAAAAAAAAAAAAAAAAAAAAAAAA'))) as enco
               set value_coded =
                    (select concept_id from concept
                      where uuid like '123450AAAAAAAAAAAAAAAAAAAAAAAAAAAAAA')
             where obs.encounter_id = enco.encounter_id
               and obs.concept_id =
                    (select concept_id from concept
                      where uuid like '160079AAAAAAAAAAAAAAAAAAAAAAAAAAAAAA')
               -- answer of previous c-section
               and obs.value_coded =
                    (select concept_id from concept
                      where uuid like '163155AAAAAAAAAAAAAAAAAAAAAAAAAAAAAA')
               and obs.voided = 0]
	at liquibase.changelog.ChangeSet.execute(ChangeSet.java:695) ~[liquibase-core-4.4.3.jar:?]
	at liquibase.changelog.visitor.UpdateVisitor.visit(UpdateVisitor.java:49) ~[liquibase-core-4.4.3.jar:?]
	at org.openmrs.util.DatabaseUpdater$OpenmrsUpdateVisitor.visit(DatabaseUpdater.java:861) ~[openmrs-api-2.6.15.jar:?]
	at liquibase.changelog.ChangeLogIterator$2.lambda$null$0(ChangeLogIterator.java:111) ~[liquibase-core-4.4.3.jar:?]
	at liquibase.Scope.lambda$child$0(Scope.java:166) ~[liquibase-core-4.4.3.jar:?]
	at liquibase.Scope.child(Scope.java:175) ~[liquibase-core-4.4.3.jar:?]
	at liquibase.Scope.child(Scope.java:165) ~[liquibase-core-4.4.3.jar:?]
	at liquibase.Scope.child(Scope.java:144) ~[liquibase-core-4.4.3.jar:?]
	at liquibase.changelog.ChangeLogIterator$2.lambda$run$1(ChangeLogIterator.java:110) ~[liquibase-core-4.4.3.jar:?]
	at liquibase.Scope.lambda$child$0(Scope.java:166) ~[liquibase-core-4.4.3.jar:?]
	at liquibase.Scope.child(Scope.java:175) ~[liquibase-core-4.4.3.jar:?]
	at liquibase.Scope.child(Scope.java:165) ~[liquibase-core-4.4.3.jar:?]
	at liquibase.Scope.child(Scope.java:144) ~[liquibase-core-4.4.3.jar:?]
	at liquibase.Scope.child(Scope.java:228) ~[liquibase-core-4.4.3.jar:?]
	at liquibase.changelog.ChangeLogIterator$2.run(ChangeLogIterator.java:94) ~[liquibase-core-4.4.3.jar:?]
	at liquibase.Scope.lambda$child$0(Scope.java:166) ~[liquibase-core-4.4.3.jar:?]
	at liquibase.Scope.child(Scope.java:175) ~[liquibase-core-4.4.3.jar:?]
	at liquibase.Scope.child(Scope.java:165) ~[liquibase-core-4.4.3.jar:?]
	at liquibase.Scope.child(Scope.java:144) ~[liquibase-core-4.4.3.jar:?]
	at liquibase.Scope.child(Scope.java:228) ~[liquibase-core-4.4.3.jar:?]
	at liquibase.Scope.child(Scope.java:232) ~[liquibase-core-4.4.3.jar:?]
	at liquibase.changelog.ChangeLogIterator.run(ChangeLogIterator.java:66) ~[liquibase-core-4.4.3.jar:?]
	at org.openmrs.util.DatabaseUpdater.executeChangelog(DatabaseUpdater.java:237) ~[openmrs-api-2.6.15.jar:?]
	at org.openmrs.util.DatabaseUpdater.executeChangelog(DatabaseUpdater.java:188) ~[openmrs-api-2.6.15.jar:?]
	... 10 more
Caused by: liquibase.exception.DatabaseException: You can't specify target table 'obs' for update in FROM clause [Failed SQL: (1093) update obs,
                   (select encounter_id from encounter
                     where encounter_type IN
                            (select encounter_type_id from encounter_type
                              where name like 'OB%GYN')
                      and encounter_id NOT IN
                            (select encounter_id from obs
                              where voided = 0
                                and concept_id =
                                    (select concept_id from concept
                                      where uuid like '160079AAAAAAAAAAAAAAAAAAAAAAAAAAAAAA')
                                and value_coded =
                                    (select concept_id from concept
                                      where uuid like '123450AAAAAAAAAAAAAAAAAAAAAAAAAAAAAA'))) as enco
               set value_coded =
                    (select concept_id from concept
                      where uuid like '123450AAAAAAAAAAAAAAAAAAAAAAAAAAAAAA')
             where obs.encounter_id = enco.encounter_id
               and obs.concept_id =
                    (select concept_id from concept
                      where uuid like '160079AAAAAAAAAAAAAAAAAAAAAAAAAAAAAA')
               -- answer of previous c-section
               and obs.value_coded =
                    (select concept_id from concept
                      where uuid like '163155AAAAAAAAAAAAAAAAAAAAAAAAAAAAAA')
               and obs.voided = 0]
	at liquibase.executor.jvm.JdbcExecutor$ExecuteStatementCallback.doInStatement(JdbcExecutor.java:393) ~[liquibase-core-4.4.3.jar:?]

@ibacher , what would you suggest we do to improve the robustness of this database.getConnection().close(); line of code that sometimes fails . Thanks!

cioan · February 17, 2025, 6:13pm

@ibacher , I take back the previous assumption. The getConnection() line fails before attempting to close the previous connection:

but then if I run in the intelliJ debugger getConnection(); returns successfully:

so, maybe it’s just a strange timing issue?

dkayiwa · February 18, 2025, 12:22pm

FWIW, i have just successfully set up the mirebalais,mirebalais-humci config of the PIH EMR with the OpenMRS SDK connecting to a MySQL 8 docker container on my Apple M1 Max.