I'm using Liquibase in all my projects, I really love the way it handles db updates, but recently I'm having this issue:
liquibase : Successfully acquired change log lock
liquibase : Successfully released change log lock
liquibase : Could not release lock
liquibase.exception.LockException: liquibase.exception.DatabaseException: liquibase.exception.DatabaseException: com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: Communications link failure during rollback(). Transaction resolution unknown.
at liquibase.lockservice.StandardLockService.releaseLock(StandardLockService.java:283) ~[liquibase-core-3.5.5.jar!/:na]
at liquibase.Liquibase.update(Liquibase.java:218) [liquibase-core-3.5.5.jar!/:na]
at liquibase.Liquibase.update(Liquibase.java:192) [liquibase-core-3.5.5.jar!/:na]
.
.
.
Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: Communications link failure during rollback(). Transaction resolution unknown.
.
.
liquibase : Failed to restore the auto commit to true
.
.
Caused by: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
The last packet successfully received from the server was 16,913 milliseconds ago. The last packet sent successfully to the server was 89 milliseconds ago.
.
.
Caused by: java.lang.NullPointerException: null
at com.mysql.jdbc.MysqlIO.clearInputStream(MysqlIO.java:899) ~[mysql-connector-java-5.1.46.jar!/:5.1.46]
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2477) ~[mysql-connector-java-5.1.46.jar!/:5.1.46]
I have 3 apps running on my server. One of them running for about 2years. The second running for 2 months and the third one is new.
They are all Spring Boot applications.
This started happening when I want to update the jar of the second app, I stopped the old jar, run the new one and I can not get it to start with the error above. Then I run the old jar of the same app and it started just fine. I try stopping and restarting this old jar and a few times I get the error above but most of the times it started just fine.
I try restarting the server (all three apps start as services with system boot) but none of them successfully start because of the same error. Not even the one running for 2 years. I stop all other apps and try again with this long-lasting app, it kept failing until it started.
Could it be a memory issue? I'm using a DigitalOcean droplet with 1 Core and 2gb RAM.
Also, what I've notice is that when it successfully start the logs looks like:
liquibase : Successfully acquired change log lock
liquibase : Reading from myDataBase.DATABASECHANGELOG
liquibase : Successfully released change log lock
Note the statement between the acquisition and release of the lock. I also suspect about a timing issue, between acquiring the lock and reading the changelog. But don't know if I can increase that time or how can I do it.
I don't known the source of the issue, but after updating the liquibase-core to v3.7.0 all the apps started correctly
About the previous update, I was testing as is not that the problem is solved, is just less frequent. But it has happen
After some digging I realize that by the same time this happen, the team was playing around with DB Connection Pool. The application.properties files contain this:
spring.datasource.tomcat.initial-size=5
spring.datasource.tomcat.max-wait=20000
spring.datasource.tomcat.max-active=5
spring.datasource.tomcat.max-idle=5
spring.datasource.tomcat.min-idle=5
spring.datasource.tomcat.default-auto-commit=true
Sadly I don't understand much about DB Pool. But what raise my attention was the last line about the auto-commit. The last time this error pops up. I disable all those lines and the app started fine. I don't know if it was just coincidence or not.
Thank you very much!
I'm back to square one... I don't know how to solve this any clue would be appreciatted
I updated mysql-connector-java to v8.0.15. My server has MySQL v5.6.33. I'm still having this issue and now I can not restart my app.
After the above change, now the exception ends with:
The last packet successfully received from the server was 10,036 milliseconds ago. The last packet sent successfully to the server was 10,036 milliseconds ago.
.
.
.
Caused by: java.io.IOException: Socket is closed
at com.mysql.cj.protocol.AbstractSocketConnection.getMysqlInput(AbstractSocketConnection.java:72) ~[mysql-connector-java-8.0.15.jar!/:8.0.15]
at com.mysql.cj.protocol.a.NativeProtocol.clearInputStream(NativeProtocol.java:833) ~[mysql-connector-java-8.0.15.jar!/:8.0.15]
... 92 common frames omitted
In a moment of clarity I decided to disable liquibase from my project, by setting liquibase.enabled=false in the application.properties. Now I can start/stop/restart the app anytime with no problem. As I only use liquibase to mantain the DataBase, and the changes I made are executed (the problem is when releasing the lock), I will enable Liquibase just to update the schema and then disable it to run the app
I kept stoping and starting the apps over and over and every time I did it I get the Socket is closed so I began to make my head around a timing issue... From the exceptions thrown I notice that every time it says that:
The last packet successfully received from the server was xxxx milliseconds ago.
The smallest value I get of those milliseconds ago was 10.085 and by chance I have some logs of the same app from time ago when this issue never pop-up. From those logs statements I meassure the time between acquiring the change-log-lock and releasing it. To my surprise it was around 9 seconds and never above that.
So I login to mysql console and issue:
show variables LIKE '%timeout%';
Which gave me a list of the defined timeouts. And there it was connect_timeout was the smallest and set to 10 seconds. It has to be it.
I googled how to set that value. I've try creating a file /etc/my.cnf and adding to it:
[mysqld]
connect_timeout=20
Then restart mysql with:
sudo /etc/init.d/mysql restart
But when I log back to the mysql console the value was still 10. So in the mysql console I issued this other command:
SET GLOBAL connect_timeout=20;
And the value was updated (I don't know if this will persist after a restart)
I restart mysql again and... voilà! Now the apps start normally with liquibase enabled. I'm happy! :-)
I kept stoping and starting the apps over and over and every time I did it I get the Socket is closed so I began to make my head around a timing issue... From the exceptions thrown I notice that every time it says that:
The last packet successfully received from the server was xxxx milliseconds ago.
The smallest value I get of those milliseconds ago was 10.085 and by chance I have some logs of the same app from time ago when this issue never pop-up. From those logs statements I meassure the time between acquiring the change-log-lock and releasing it. To my surprise it was around 9 seconds and never above that.
So I login to mysql console and issue:
show variables LIKE '%timeout%';
Which gave me a list of the defined timeouts. And there it was connect_timeout was the smallest and set to 10 seconds. It has to be it.
I googled how to set that value. I've try creating a file /etc/my.cnf and adding to it:
[mysqld]
connect_timeout=20
Then restart mysql with:
sudo /etc/init.d/mysql restart
But when I log back to the mysql console the value was still 10. So in the mysql console I issued this other command:
SET GLOBAL connect_timeout=20;
And the value was updated (I don't know if this will persist after a full server restart)
I restart mysql again and... voilà! Now the apps start normally with liquibase enabled. I'm happy! :-)