Sometime, MySQL connection failure
Oruss7 opened this issue ยท 21 comments
Some day, zhorse flood my server log with this message.
MySQL is ok, other plugins work fines with it.
The last packet successfully received from the server was 29 525 764 milliseconds ago. The last packet sent successfully to the server was 0 milliseconds ago.
[16:29:26] [Server thread/WARN]: at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
[16:29:26] [Server thread/WARN]: at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
[16:29:26] [Server thread/WARN]: at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
[16:29:26] [Server thread/WARN]: at java.lang.reflect.Constructor.newInstance(Constructor.java:422)
[16:29:26] [Server thread/WARN]: at com.mysql.jdbc.Util.handleNewInstance(Util.java:404)
[16:29:26] [Server thread/WARN]: at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:988)
[16:29:26] [Server thread/WARN]: at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3552)
[16:29:26] [Server thread/WARN]: at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3452)
[16:29:26] [Server thread/WARN]: at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3893)
[16:29:26] [Server thread/WARN]: at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2526)
[16:29:26] [Server thread/WARN]: at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2673)
[16:29:26] [Server thread/WARN]: at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2545)
[16:29:26] [Server thread/WARN]: at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2503)
[16:29:26] [Server thread/WARN]: at com.mysql.jdbc.StatementImpl.executeQuery(StatementImpl.java:1369)
[16:29:26] [Server thread/WARN]: at eu.reborn_minecraft.zhorse.utils.SQLDatabaseConnector.hasResult(SQLDatabaseConnector.java:113)
[16:29:26] [Server thread/WARN]: at eu.reborn_minecraft.zhorse.managers.DataManager.isPlayerRegistered(DataManager.java:242)
[16:29:26] [Server thread/WARN]: at eu.reborn_minecraft.zhorse.utils.DelayedPlayerJoin$1.run(DelayedPlayerJoin.java:17)
[16:29:26] [Server thread/WARN]: ... 7 more
[16:29:26] [Server thread/WARN]: Caused by: java.io.EOFException: Can not read response from server. Expected to read 4 bytes, read 0 bytes before connection was unexpectedly lost.
[16:29:26] [Server thread/WARN]: at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3004)
[16:29:26] [Server thread/WARN]: at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3462)
[16:29:26] [Server thread/WARN]: ... 17 more
[16:29:26] [Server thread/WARN]: com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: No operations allowed after connection closed.
[16:29:26] [Server thread/WARN]: at sun.reflect.GeneratedConstructorAccessor179.newInstance(Unknown Source)
[16:29:26] [Server thread/WARN]: at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
[16:29:26] [Server thread/WARN]: at java.lang.reflect.Constructor.newInstance(Constructor.java:422)
[16:29:26] [Server thread/WARN]: at com.mysql.jdbc.Util.handleNewInstance(Util.java:404)
[16:29:26] [Server thread/WARN]: at com.mysql.jdbc.Util.getInstance(Util.java:387)
[16:29:26] [Server thread/WARN]: at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:917)
[16:29:26] [Server thread/WARN]: at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:896)
[16:29:26] [Server thread/WARN]: at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:885)
[16:29:26] [Server thread/WARN]: at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:860)
[16:29:26] [Server thread/WARN]: at com.mysql.jdbc.ConnectionImpl.throwConnectionClosedException(ConnectionImpl.java:1246)
[16:29:26] [Server thread/WARN]: at com.mysql.jdbc.ConnectionImpl.checkClosed(ConnectionImpl.java:1241)
[16:29:26] [Server thread/WARN]: at com.mysql.jdbc.ConnectionImpl.createStatement(ConnectionImpl.java:2436)
[16:29:26] [Server thread/WARN]: at com.mysql.jdbc.ConnectionImpl.createStatement(ConnectionImpl.java:2420)
[16:29:26] [Server thread/WARN]: at eu.reborn_minecraft.zhorse.utils.SQLDatabaseConnector.hasResult(SQLDatabaseConnector.java:112)
[16:29:26] [Server thread/WARN]: at eu.reborn_minecraft.zhorse.managers.DataManager.isHorseRegistered(DataManager.java:222)
[16:29:26] [Server thread/WARN]: at eu.reborn_minecraft.zhorse.utils.DelayedChunckUnload$1.run(DelayedChunckUnload.java:20)
[16:29:26] [Server thread/WARN]: at org.bukkit.craftbukkit.v1_11_R1.scheduler.CraftTask.run(CraftTask.java:71)
[16:29:26] [Server thread/WARN]: at org.bukkit.craftbukkit.v1_11_R1.scheduler.CraftScheduler.mainThreadHeartbeat(CraftScheduler.java:353)
[16:29:26] [Server thread/WARN]: at net.minecraft.server.v1_11_R1.MinecraftServer.D(MinecraftServer.java:730)
[16:29:26] [Server thread/WARN]: at net.minecraft.server.v1_11_R1.DedicatedServer.D(DedicatedServer.java:399)
[16:29:26] [Server thread/WARN]: at net.minecraft.server.v1_11_R1.MinecraftServer.C(MinecraftServer.java:675)
[16:29:26] [Server thread/WARN]: at net.minecraft.server.v1_11_R1.MinecraftServer.run(MinecraftServer.java:574)
[16:29:26] [Server thread/WARN]: at java.lang.Thread.run(Thread.java:745)
[16:29:26] [Server thread/WARN]: Caused by: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
Maybe, I'm not really an expert with jdbc so I'll make some tests and look for documentation.
I'm working on several things in the same time on ZHorse so, if it spams too much, you should switch temporarily to SQLite.
You can import your current data in SQLite (and back to MySQL) with /zh admin import. More explanations with the in-game help or in the Tips and tricks page ;)
It seems to be a very frequent issue across the internet that has many fixes but, unfortunately, most fixes only work in particular cases.
There exist some lists of these fixes and I'm afraid that we will have to try them one by one...
Some of them require changes on the MySQL server, others in the plugin code. We will begin by changing the code.
A few of those are already included in ZHorse, so we will now try the autoReconnect option of JDBC included in this snapshot : http://www.mediafire.com/file/xm5e80d85vto8g8/ZHorse+1.6.4+snapshot+2.jar
This includes all the changes that I made since 27/Jan/2017, available here : https://github.com/Xibalba/ZHorse/commits/master
IMPORTANT : As this is only a snapshot, the database structure might change again before the release of 1.6.4. If this is the case, I'll provide you in this ticket the SQL queries to apply to your MySQL server.
I am experiencing this too. My server reboots each day, and the reboot fixes that, but approximately once per 2 days this happens and ZHorse doesn't work until reboot.
UPD: /zh reload also helps to work around this.
Could this log snippet be suggesting a good solution?
[08:31:47 WARN]: Caused by: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: The last packet successfully received from the server was 37,357,262 milliseconds ago. The last packet sent successfully to the server was 37,357,262 milliseconds ago. is longer than the server configured value of 'wait_timeout'. You should consider either expiring and/or testing connection validity before use in your application, increasing the server configured values for client timeouts, or using the Connector/J connection property 'autoReconnect=true' to avoid this problem.
I tried this version and I have this bug :
[23:51:25] [Server thread/WARN]: com.mysql.jdbc.exceptions.jdbc4.MySQLIntegrityConstraintViolationException: Duplicate entry '273f91ba-4d9d-42a2-94a3-1ce6efc2ab23' for key 'PRIMARY'
[23:51:25] [Server thread/WARN]: at sun.reflect.GeneratedConstructorAccessor304.newInstance(Unknown Source)
[23:51:25] [Server thread/WARN]: at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
[23:51:25] [Server thread/WARN]: at java.lang.reflect.Constructor.newInstance(Constructor.java:422)
[23:51:25] [Server thread/WARN]: at com.mysql.jdbc.Util.handleNewInstance(Util.java:404)
[23:51:25] [Server thread/WARN]: at com.mysql.jdbc.Util.getInstance(Util.java:387)
[23:51:25] [Server thread/WARN]: at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:934)
[23:51:25] [Server thread/WARN]: at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3966)
[23:51:25] [Server thread/WARN]: at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3902)
[23:51:25] [Server thread/WARN]: at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2526)
[23:51:25] [Server thread/WARN]: at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2673)
[23:51:25] [Server thread/WARN]: at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2545)
[23:51:25] [Server thread/WARN]: at com.mysql.jdbc.StatementImpl.executeUpdateInternal(StatementImpl.java:1540)
[23:51:25] [Server thread/WARN]: at com.mysql.jdbc.StatementImpl.executeLargeUpdate(StatementImpl.java:2595)
[23:51:25] [Server thread/WARN]: at com.mysql.jdbc.StatementImpl.executeUpdate(StatementImpl.java:1468)
[23:51:25] [Server thread/WARN]: at eu.reborn_minecraft.zhorse.database.SQLDatabaseConnector.executeUpdate(SQLDatabaseConnector.java:55)
[23:51:25] [Server thread/WARN]: at eu.reborn_minecraft.zhorse.managers.DataManager.registerHorseStats(DataManager.java:319)
[23:51:25] [Server thread/WARN]: at eu.reborn_minecraft.zhorse.utils.DelayedChunckUnload$1.run(DelayedChunckUnload.java:25)
[23:51:25] [Server thread/WARN]: at org.bukkit.craftbukkit.v1_11_R1.scheduler.CraftTask.run(CraftTask.java:71)
[23:51:25] [Server thread/WARN]: at org.bukkit.craftbukkit.v1_11_R1.scheduler.CraftScheduler.mainThreadHeartbeat(CraftScheduler.java:353)
[23:51:25] [Server thread/WARN]: at net.minecraft.server.v1_11_R1.MinecraftServer.D(MinecraftServer.java:730)
[23:51:25] [Server thread/WARN]: at net.minecraft.server.v1_11_R1.DedicatedServer.D(DedicatedServer.java:399)
[23:51:25] [Server thread/WARN]: at net.minecraft.server.v1_11_R1.MinecraftServer.C(MinecraftServer.java:675)
[23:51:25] [Server thread/WARN]: at net.minecraft.server.v1_11_R1.MinecraftServer.run(MinecraftServer.java:574)
[23:51:25] [Server thread/WARN]: at java.lang.Thread.run(Thread.java:745)
The name of the primary changes between the difference stacks but the error stay the same.
Ok this is a bug in the work in progress, revert back to the last stable release for now. A real snapshot for 1.6.4 should be ready soon
Sorry for the delay, I was much more busy this month than I expected... I should be able to finish this snapshot for the first week of March.
Hi, I finally got back to work on this snapshot :)
I made several changes (one that might mix your issue @Eredrim) to the code and the SQL tables so here is the SQL script that you must run just before installing ZHorse 1.6.4 snapshot 3 (I assume that the prefix for tables is "zh":
USE zhorse; DROP TABLE IF EXISTS zh_horse_stats; DROP TABLE IF EXISTS zh_horse_inventory
Please update asap to snapshot 4 : http://www.mediafire.com/file/dl03p2335sxpc43/ZHorse+1.6.4+snapshot+4.jar
It fixes an issue when donkey's chest contains custom items or shulker boxes.
BTW this will be the last snapshot posted here because it diverged too much since the ticket was created.
I changed the structure of SQL tables again, so before updating to ZHorse 1.6.4 snapshot 5 (or higher), be sure to execute this : USE zhorse; DROP TABLE IF EXISTS zh_horse_inventory
As there have been no updates about this, I close the ticket.
I will open it again if necessary.
I have this stack error with snapshot 4 :
[Server thread/WARN]: [ZHorse] Task #97391 for ZHorse v1.6.4 snapshot 4 generated an exception
java.lang.NoSuchMethodError: org.bukkit.inventory.meta.ItemMeta.hasLocalizedName()Z
at eu.reborn_minecraft.zhorse.database.InventoryItemRecord.(InventoryItemRecord.java:80) ~[?:?]
at eu.reborn_minecraft.zhorse.database.HorseInventoryRecord.(HorseInventoryRecord.java:31) ~[?:?]
at eu.reborn_minecraft.zhorse.utils.DelayedChunckUnload$1.run(DelayedChunckUnload.java:26) ~[?:?]
at org.bukkit.craftbukkit.v1_11_R1.scheduler.CraftTask.run(CraftTask.java:71) ~[spigot-1.11.2.jar:git-Spigot-65a0347-a552117]
at org.bukkit.craftbukkit.v1_11_R1.scheduler.CraftScheduler.mainThreadHeartbeat(CraftScheduler.java:353) [spigot-1.11.2.jar:git-Spigot-65a0347-a552117]
at net.minecraft.server.v1_11_R1.MinecraftServer.D(MinecraftServer.java:738) [spigot-1.11.2.jar:git-Spigot-65a0347-a552117]
at net.minecraft.server.v1_11_R1.DedicatedServer.D(DedicatedServer.java:399) [spigot-1.11.2.jar:git-Spigot-65a0347-a552117]
at net.minecraft.server.v1_11_R1.MinecraftServer.C(MinecraftServer.java:678) [spigot-1.11.2.jar:git-Spigot-65a0347-a552117]
at net.minecraft.server.v1_11_R1.MinecraftServer.run(MinecraftServer.java:576) [spigot-1.11.2.jar:git-Spigot-65a0347-a552117]
at java.lang.Thread.run(Thread.java:745) [?:1.8.0_60]
This errors occurred many times today but not regularly.
This may be because your Spigot version is outdated.
But anyway, I'm not using it anymore since snapshot 5 : http://www.mediafire.com/file/cl88j9x2535q216/ZHorse+1.6.4+snapshot+5.jar
(Please don't forget to execute USE zhorse; DROP TABLE IF EXISTS zh_horse_inventory before updating)
Also, be aware that all the features planned for the release of 1.6.4 are finished in the snapshot 5 but I'm currently dealing with high CPU usage, so it's up to you to update or not :p