Queue overloaded because of 'null'

TheE commented 9 years ago

Using HawkEye Reloaded devBuild#55 (commit b4da955fa5fb34aacc7034e150975adb132fb7f7) on Spigot 1.8.7, the queue fills up but is never written to the database:

[23:36:35 INFO]: [HawkEye] The queue is almost overloaded! Queue: 27698346
[23:36:35 WARN]: [HawkEye] null
[23:36:37 INFO]: [HawkEye] The queue is almost overloaded! Queue: 27701705
[23:36:37 WARN]: [HawkEye] null
[23:36:39 INFO]: [HawkEye] The queue is almost overloaded! Queue: 27705064
[23:36:39 WARN]: [HawkEye] null

When shutting down the server, I see the following error message:

[23:38:18 ERROR]: [HawkEye] Error whilst attempting to get connection: com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: Too many connections
[23:38:18 WARN]: [HawkEye] null
[23:38:18 INFO]: [HawkEye] The queue is almost overloaded! Queue: 27840282
[23:38:18 ERROR]: [HawkEye] Error whilst attempting to get connection: com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: Too many connections
[23:38:18 WARN]: [HawkEye] null
[23:38:18 ERROR]: [HawkEye] Unable to close SQL connection: java.lang.NullPointerException
[23:38:18 INFO]: [HawkEye] Version 1.6.2 disabled!

I also activated HawkEye's debug output, but did not notice anything unusual. HawkEye Reloaded was updated from 1.6.2 and no changes where made to the configuration. Likewise there where no changes made in the MySQL server's configuration.

I assume that this is a bug within HawkEye. Please let me know if I can help you to track it down and resolve it.

bob7l commented 9 years ago

Very weird. Only thing it could possibly be is a failed insertion - which might be the result of the newer worldedit API.

What HawkEye DEV build did you move from? The bukkit.dev HawkEye mysql setup is a bit different from the DEV branch.

Give this a run: https://www.dropbox.com/s/5oyxrsauzylcken/HawkEye.jar?dl=0

That'll just output more detailed errors

TheE commented 9 years ago

I updated from devBuild#44 (commit 458806c430f108942bc7259606ea86c657f85fcd). When updating to devBuild#55 that database was convert by HawkEye. Is there a chance of a misconfiguration?

I updated to the build you provided. On startup I see:

[00:23:48 INFO]: [HawkEye] Enabling HawkEye v1.6.2
[00:23:48 INFO]: [HawkEye] Starting HawkEye 1.6.2 initiation process...
[00:23:48 INFO]: [HawkEye] DEBUG: Attempting to connecting to database at: jdbc:mysql://localhost:3306/minecraft
[00:23:48 INFO]: [HawkEye] DEBUG: No available MySQL connections, attempting to create new one

On shutdown I see:

[00:23:11 INFO]: [HawkEye] Disabling HawkEye v1.6.2
[00:23:11 INFO]: [HawkEye] DEBUG: Not ready
[00:23:11 INFO]: [HawkEye] DEBUG: No available MySQL connections, attempting to create new one
[00:23:11 INFO]: [HawkEye] DEBUG: Not ready
[00:23:11 INFO]: [HawkEye] DEBUG: No available MySQL connections, attempting to create new one
[00:23:11 INFO]: [HawkEye] DEBUG: Not ready
[00:23:11 INFO]: [HawkEye] DEBUG: No available MySQL connections, attempting to create new one
[00:23:11 INFO]: [HawkEye] DEBUG: Not ready
[00:23:11 INFO]: [HawkEye] DEBUG: No available MySQL connections, attempting to create new one
[00:23:11 INFO]: [HawkEye] DEBUG: Not ready
[00:23:11 INFO]: [HawkEye] DEBUG: No available MySQL connections, attempting to create new one
[00:23:11 INFO]: [HawkEye] DEBUG: Not ready
[00:23:11 INFO]: [HawkEye] DEBUG: No available MySQL connections, attempting to create new one
[00:23:11 INFO]: [HawkEye] DEBUG: Not ready
[00:23:11 INFO]: [HawkEye] DEBUG: No available MySQL connections, attempting to create new one
[00:23:11 INFO]: [HawkEye] DEBUG: Not ready
[00:23:11 INFO]: [HawkEye] DEBUG: No available MySQL connections, attempting to create new one
[00:23:11 INFO]: [HawkEye] DEBUG: Not ready
[00:23:11 INFO]: [HawkEye] DEBUG: No available MySQL connections, attempting to create new one
[00:23:11 INFO]: [HawkEye] DEBUG: Not ready
[00:23:11 INFO]: [HawkEye] DEBUG: No available MySQL connections, attempting to create new one
[00:23:11 INFO]: [HawkEye] DEBUG: Not ready
[00:23:11 INFO]: [HawkEye] DEBUG: Closing all MySQL connections

There are no messages indicating that the queue is overloaded, - however, the server is currently almost empty so there is not enough data to overload it.

bob7l commented 9 years ago

Yeah you're having issues because it most likely failed to update your database. Only way to fix is to remove the old database files and let hawkeye auto-regenerate the tables.

bob7l commented 9 years ago

Or just for testing, change the table names in the config and see if the problem still exists.

TheE commented 9 years ago

Today the queue was overloaded once more. However the error message was quit helpful:

[21:18:14 INFO]: [HawkEye] DEBUG: Attempting to add world 'end' to database
[21:18:14 WARN]: [HawkEye] null
[21:18:14 WARN]: java.lang.NullPointerException
[21:18:14 WARN]:        at uk.co.oliwali.HawkEye.database.DataManager.run(DataManager.java:429)
[21:18:14 WARN]:        at org.bukkit.craftbukkit.v1_8_R3.scheduler.CraftTask.run(CraftTask.java:71)
[21:18:14 WARN]:        at org.bukkit.craftbukkit.v1_8_R3.scheduler.CraftAsyncTask.run(CraftAsyncTask.java:53)
[21:18:14 WARN]:        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
[21:18:14 WARN]:        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
[21:18:14 WARN]:        at java.lang.Thread.run(Thread.java:745)
[21:18:16 INFO]: [HawkEye] The queue is almost overloaded! Queue: 771906

The NPE occurs when HawkEye tries to read the world_id from the database. Upon inspection it turned out that the record of the world in question (end) was stored as End. After correcting this error, everything appears to work fine.

bob7l commented 9 years ago

That's really weird? Shouldn't the END be called "world_the_end"?

What plugin did you use to generate "end'?

TheE commented 9 years ago

The world was manually generated with Multiverse, the name is fully intended.

From reading the source code, I think the bug can be understood as follows:

run() is called for an event on end.
dbWorlds.containsKey("end") returns false, therefore addWorld("end") is called.
This method sends the query INSERT IGNORE INTOhawk_worlds(world) VALUES ('end'); to the database.
The database will do nothing because hawk_worlds is defined as case-insensitive (latin1_general_ci) and it already contains End witch is case-insensitively equal to end. This behaviour is defined by the IGNORE definition.
updateDbLists() recreates the dbWorlds map.without any errors. But because nothing was actually written to the database, the recreated map contains the same entries as before.
Therefore addWorld("end") returns true.
run() continues. When it sets the world-id (line 429), it calls dbWorlds.get("end").
As described above, dbWorlds cannot contain end but End and returns null.
smnt.setInt(4, null) throws an NPE.

It seems like HawkEye does not support setups with worlds that are only case-sensitively different. However this should be relatively easy to fix by either dropping the case-insensitive definition of the worlds table or using the world's UUID instead of the name.

bob7l commented 9 years ago

Ahh the IGNORE tag... Nothing but issues come from that damn tag. I'll replace it soon

bob7l / HawkReloaded

Queue overloaded because of 'null' #48