Database stack on shutdown

[ttk2]

Seeing this on every shutdown of any server on the current civtemp setup, no other RB stacks during operation.

The last packet successfully received from the server was 1,054,999 milliseconds ago. The last packet sent successfully to the server was 0 milliseconds ago.
2016-02-12 17:01:32 [ERROR] [RealisticBiomes] error in run() when shutting down!
com.avaje.ebeaninternal.server.lib.sql.DataSourceException: unable to set autocommit to false in saveAllAndStop
at com.untamedears.realisticbiomes.persist.PlantManager$3.run(PlantManager.java:368) [RealisticBiomes-1.0.4.jar:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_66-internal]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_66-internal]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:1.8.0_66-internal]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:1.8.0_66-internal]
at java.lang.Thread.run(Thread.java:745) [?:1.8.0_66-internal]
Caused by: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure

The last packet successfully received from the server was 1,054,999 milliseconds ago. The last packet sent successfully to the server was 0 milliseconds ago.
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) ~[?:1.8.0_66-internal]
at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62) ~[?:1.8.0_66-internal]
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[?:1.8.0_66-internal]
at java.lang.reflect.Constructor.newInstance(Constructor.java:422) ~[?:1.8.0_66-internal]
at com.mysql.jdbc.Util.handleNewInstance(Util.java:407) ~[spigot.jar:git-Spigot-db6de12-880a532]
at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:1116) ~[spigot.jar:git-Spigot-db6de12-880a532]
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3082) ~[spigot.jar:git-Spigot-db6de12-880a532]
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2968) ~[spigot.jar:git-Spigot-db6de12-880a532]
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3516) ~[spigot.jar:git-Spigot-db6de12-880a532]
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1986) ~[spigot.jar:git-Spigot-db6de12-880a532]
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2140) ~[spigot.jar:git-Spigot-db6de12-880a532]
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2620) ~[spigot.jar:git-Spigot-db6de12-880a532]
at com.mysql.jdbc.ConnectionImpl.setAutoCommit(ConnectionImpl.java:5022) ~[spigot.jar:git-Spigot-db6de12-880a532]
at com.untamedears.realisticbiomes.persist.PlantManager$3.run(PlantManager.java:365) ~[?:?]
... 5 more
Caused by: java.io.EOFException: Can not read response from server. Expected to read 4 bytes, read 0 bytes before connection was unexpectedly lost.
at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:2529) ~[spigot.jar:git-Spigot-db6de12-880a532]
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2979) ~[spigot.jar:git-Spigot-db6de12-880a532]
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2968) ~[spigot.jar:git-Spigot-db6de12-880a532]
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3516) ~[spigot.jar:git-Spigot-db6de12-880a532]
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1986) ~[spigot.jar:git-Spigot-db6de12-880a532]
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2140) ~[spigot.jar:git-Spigot-db6de12-880a532]
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2620) ~[spigot.jar:git-Spigot-db6de12-880a532]
at com.mysql.jdbc.ConnectionImpl.setAutoCommit(ConnectionImpl.java:5022) ~[spigot.jar:git-Spigot-db6de12-880a532]
at com.untamedears.realisticbiomes.persist.PlantManager$3.run(PlantManager.java:365) ~[?:?]
... 5 more

[Arebs]

Hey there, I looked over the problem and got a question: Why is ExecutorService used here to write in the DB at the end? As far as I know, JDCB doesn't support asynchronous calls. If you want, I can debug this later (in about 8-9 hours) and fix the Problem

[ProgrammerDan]

It's a timeout problem. When a server isn't in active use, it holds the connection open past MariaDB/MySQL's configured timeout, and on next-write the connection fails. Up until the write, however, the connection self-reports as being alive and well.

One fix for this is simple, just run an asynchronous process that sends a keepalive query to MySQL (something like "SELECT 1;") every minute or two. The other fix would be to use an actual connection pool, which would handle these kinds of problems for us.

@Arebs If I recall, the asynchronous bit is simply a thread is spawned to handle the dump to the database so that the rest of the shutdown process can continue without being delayed by the cache dump to RealisticBiome's database. As for JDBC itself, it's not an asynchronous call, per sey; all the calls against the driver are well-ordered and "synchronous" from its point of view, however, the thread that utilizes JDBC can absolutely be "asynchronous" from the main application's point of view.

[Arebs]

@ProgrammerDan ahh, now I understand, thanks. The first Solution may sound simple, but this will not work if the Connection get lost or terminated. The Connection Pool sounds like a good solution, either in a singleton for the complete Plugin or simple in the Class

[ProgrammerDan]

So, I'd recommend the first version for now. Longer term switching to a connection pool is planned, but would ideally need to be applied consistently across all the plugins leveraging database.

In that case it'd probably be worthwhile rolling the pooling up into CivModCore and enforcing that each plugin extend from there.

[erocs]

That was the plan. I think there was even an open issue to move DB handling
to CivModCore so a connection pool could be used.

On Wed, Feb 17, 2016 at 9:14 AM, Daniel Boston notifications@github.com
wrote:

So, I'd recommend the first version for now. Longer term switching to a
connection pool is planned, but would ideally need to be applied
consistently across all the plugins leveraging database.

In that case it'd probably be worthwhile rolling the pooling up into
CivModCore and enforcing that each plugin extend from there.

—
Reply to this email directly or view it on GitHub
#71 (comment)
.