Exception
EvilOlaf opened this issue · 36 comments
[07:53:30] [Craft Scheduler Thread - 280/WARN]: Exception in thread "Craft Scheduler Thread - 280"
[07:53:30] [Craft Scheduler Thread - 280/WARN]: org.apache.commons.lang.UnhandledException: Plugin BanManager v5.6.0 generated an exception while executing task 34
at org.bukkit.craftbukkit.v1_8_R3.scheduler.CraftAsyncTask.run(CraftAsyncTask.java:56)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.IllegalStateException: Errors getting more results of class me.confuser.banmanager.data.PlayerBanData
at me.confuser.banmanager.internal.ormlite.stmt.SelectIterator.hasNext(SelectIterator.java:103)
at me.confuser.banmanager.runnables.BanSync.newBans(BanSync.java:48)
at me.confuser.banmanager.runnables.BanSync.run(BanSync.java:32)
at org.bukkit.craftbukkit.v1_8_R3.scheduler.CraftTask.run(CraftTask.java:71)
at org.bukkit.craftbukkit.v1_8_R3.scheduler.CraftAsyncTask.run(CraftAsyncTask.java:53)
... 3 more
Caused by: java.sql.SQLException: Operation not allowed after ResultSet closed
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1073)
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:987)
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:982)
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:927)
at com.mysql.jdbc.ResultSetImpl.checkClosed(ResultSetImpl.java:794)
at com.mysql.jdbc.ResultSetImpl.next(ResultSetImpl.java:7145)
at me.confuser.banmanager.internal.ormlite.jdbc.JdbcDatabaseResults.next(JdbcDatabaseResults.java:64)
at me.confuser.banmanager.internal.ormlite.stmt.SelectIterator.hasNextThrow(SelectIterator.java:81)
at me.confuser.banmanager.internal.ormlite.stmt.SelectIterator.hasNext(SelectIterator.java:98)
... 7 more
BM5.6.0 @ Spigot 1.8.7
If you need more information, please let me know.
I'm fairly certain this problem is caused by different scheduled tasks attempting to use the same connection across different threads. Unfortunately the developer of the orm library isn't overly active, so will need to come up with a work around on this end.
Possible fix pushed, those watching this thread, can you test it please. I haven't yet tested it, hence [UNTESTED] comment in the commit.
I downgraded to build 191 twice after noticing the occurring exceptions as new issue reports. I'll give it a new try after those have been fixed :)
I have not been able to test. But out of curiosity, is that error just annoying or is it breaking a system?
Ok. If all else fails, could eat the error the first time and try again immediately?
Potentially, but then it may start throwing an overflow exception instead. The latest commit referenced in this issue should however fix it. The main issue appears to be a concurrency issue with the ORM I'm using. So to solve it, I've changed the way tasks are run. Instead of running individually in their own bukkit worker thread, they now all run in the same thread, sequentially.
@EvilOlaf they should both be fixed in the latest build.
Aight, will give it another try.
Stay tuned.
@Iceee I'm using BM with this exception for quite a while now and never had an issue with it. So far for me it is an optical issue.
Spigots logrotate automatically gzips previous latest.log.
So for searching through multiple old files you may consider using something like
zcat 2015-10-*.log.gz | grep ........and so on ;)
You do not need to cat before grepping, grep does this already when specifying a filename.
Looks good so far.
However this needs to be monitored for at least a few days.
Will check up here in a week or two.
I can't remember your setup @EvilOlaf, are you using any form of syncing between servers? If so, any issues with it?
Ideally I'm aiming to make a release for 5.7 at the weekend which contains this fix as it's causing a lot of bug reports thinking BM is buggy.
Nope and nope ;)
If you think this will solve this issue do the release. If you want to stay safe gimme a few days to watch the log files :). If I don't complain about anything, everything works well.
A little tip for anyone who is searching through logs manually for exceptions on a linux instance.
cat LOGFILEHERE | grep --text "ERROR\|FATAL\|Exception\|at.*\.java\:.*" | grep -v "lost connection" > errors.txt
Replace LOGFILEHERE with the file name, e.g. server.log. It'll output all errors into a file named errors.txt
I've opened an issue on the ORM library as I'm at a loss as to the exact cause of this. Something is closing the result set before the iteration is complete, causing this error to be thrown.
Probably related to this one. BM5.6.1 @ Spigot 1.8.8
[09:25:10 WARN]: org.apache.commons.lang.UnhandledException: Plugin BanManager v5.6.1 generated an exception while executing task 33
at org.bukkit.craftbukkit.v1_8_R3.scheduler.CraftAsyncTask.run(CraftAsyncTask.java:56)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.IllegalStateException: Errors getting more results of class me.confuser.banmanager.data.PlayerBanData
at me.confuser.banmanager.internal.ormlite.stmt.SelectIterator.hasNext(SelectIterator.java:103)
at me.confuser.banmanager.runnables.BanSync.newBans(BanSync.java:48)
at me.confuser.banmanager.runnables.BanSync.run(BanSync.java:32)
at org.bukkit.craftbukkit.v1_8_R3.scheduler.CraftTask.run(CraftTask.java:71)
at org.bukkit.craftbukkit.v1_8_R3.scheduler.CraftAsyncTask.run(CraftAsyncTask.java:53)
... 3 more
Caused by: java.sql.SQLException: Operation not allowed after ResultSet closed
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1073)
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:987)
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:982)
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:927)
at com.mysql.jdbc.ResultSetImpl.checkClosed(ResultSetImpl.java:794)
at com.mysql.jdbc.ResultSetImpl.first(ResultSetImpl.java:1164)
at me.confuser.banmanager.internal.ormlite.jdbc.JdbcDatabaseResults.first(JdbcDatabaseResults.java:58)
at me.confuser.banmanager.internal.ormlite.stmt.SelectIterator.hasNextThrow(SelectIterator.java:79)
at me.confuser.banmanager.internal.ormlite.stmt.SelectIterator.hasNext(SelectIterator.java:98)
... 7 more
I'm going to re-enable the testing of connections in a developer build to see if that fixes this. It's currently disabled as someone reported it contained a memory leak, but I never saw the leak in production nor development personally.
Hello, i would like to say that i am having the same error on my server
I was looking in the console and it happened randomly, (no commands was executed)
and noone was joining / leaving the server
[18:12:01] [Craft Scheduler Thread - 11/WARN]: Exception in thread "Craft Scheduler Thread - 11"
[18:12:01] [Craft Scheduler Thread - 11/WARN]: org.apache.commons.lang.UnhandledException: Plugin BanManager v5.6.1 generated an exception while executing task 36
at org.bukkit.craftbukkit.v1_8_R3.scheduler.CraftAsyncTask.run(CraftAsyncTask.java:56)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.IllegalStateException: Errors getting more results of class me.confuser.banmanager.data.PlayerBanData
at me.confuser.banmanager.internal.ormlite.stmt.SelectIterator.hasNext(SelectIterator.java:103)
at me.confuser.banmanager.runnables.BanSync.newBans(BanSync.java:48)
at me.confuser.banmanager.runnables.BanSync.run(BanSync.java:32)
at org.bukkit.craftbukkit.v1_8_R3.scheduler.CraftTask.run(CraftTask.java:71)
at org.bukkit.craftbukkit.v1_8_R3.scheduler.CraftAsyncTask.run(CraftAsyncTask.java:53)
... 3 more
Caused by: java.sql.SQLException: Operation not allowed after ResultSet closed
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1073)
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:987)
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:982)
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:927)
at com.mysql.jdbc.ResultSetImpl.checkClosed(ResultSetImpl.java:794)
at com.mysql.jdbc.ResultSetImpl.first(ResultSetImpl.java:1164)
at me.confuser.banmanager.internal.ormlite.jdbc.JdbcDatabaseResults.first(JdbcDatabaseResults.java:58)
at me.confuser.banmanager.internal.ormlite.stmt.SelectIterator.hasNextThrow(SelectIterator.java:79)
at me.confuser.banmanager.internal.ormlite.stmt.SelectIterator.hasNext(SelectIterator.java:98)
... 7 more
´´´´
im new to coding (and im still learning), so please note that what im about to say now, may be sooo wrong :p
I opened up the file "me.confuser.banmanager.runnables.BanSync" where the stack trace is pointing,
at line 79: you are closing "itr" but never "opening" it again, meaning that the first time this code runs, it would work fine.
But the second time, it would fail cause "itr" is not available, so you need to open it again before you can edit it.
i hoped this helped you a little bit, and if not, sorry for wasting your time :)
Thats not the issue @jaboy , when the method has finished and he reruns it it will instantiate a new CloseableIterator everytime.
@EvilOlaf can you try build 177+ please and let me know if you still see these exceptions in a few days?
Sure, will do. They come quite rarely though.
Unable to download from CI. It is quite low and the download breaks after a few kilobytes. Tried several times from different locations.
The issue is that the underlying connection is closed during iteration for no reason. The latest developer build may fix ththe is issue.
Sorry @EvilOlaf I missed your comment regarding the CI server. I'll take a look.
No problem. Seems like that was a temporarily problem. I was able to get the latest dev already.
Great. Someone was probably attacking it.
On 18 Aug 2015 09:41, "Very Evil Olaf" [email protected] wrote:
No problem. Seems like that was a temporarily problem. I was able to get
the latest dev already.—
Reply to this email directly or view it on GitHub
#321 (comment)
.
[07:05:26 WARN]: Exception in thread "Craft Scheduler Thread - 240"
[07:05:26 WARN]: org.apache.commons.lang.UnhandledException: Plugin BanManager v5.7.0-SNAPSHOT generated an exception while executing task 40
at org.bukkit.craftbukkit.v1_8_R3.scheduler.CraftAsyncTask.run(CraftAsyncTask.java:56)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.IllegalStateException: Errors getting more results of class me.confuser.banmanager.data.PlayerBanData
at me.confuser.banmanager.internal.ormlite.stmt.SelectIterator.hasNext(SelectIterator.java:103)
at me.confuser.banmanager.runnables.ExpiresSync.run(ExpiresSync.java:37)
at org.bukkit.craftbukkit.v1_8_R3.scheduler.CraftTask.run(CraftTask.java:71)
at org.bukkit.craftbukkit.v1_8_R3.scheduler.CraftAsyncTask.run(CraftAsyncTask.java:53)
... 3 more
Caused by: java.sql.SQLException: Operation not allowed after ResultSet closed
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1073)
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:987)
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:982)
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:927)
at com.mysql.jdbc.ResultSetImpl.checkClosed(ResultSetImpl.java:794)
at com.mysql.jdbc.ResultSetImpl.next(ResultSetImpl.java:7145)
at me.confuser.banmanager.internal.ormlite.jdbc.JdbcDatabaseResults.next(JdbcDatabaseResults.java:64)
at me.confuser.banmanager.internal.ormlite.stmt.SelectIterator.hasNextThrow(SelectIterator.java:81)
at me.confuser.banmanager.internal.ormlite.stmt.SelectIterator.hasNext(SelectIterator.java:98)
... 6 more
@EvilOlaf Have you noticed any more of these exceptions since updating to the developer build?