[SPIGOT-2634] Concurrency issue in FileIOThread Created: 27/Aug/16  Updated: 26/Sep/16  Resolved: 27/Aug/16

Status: Resolved
Project: Spigot
Component/s: None
Affects Version/s: None
Fix Version/s: None

Type: Bug Priority: Minor
Reporter: libraryaddict Assignee: Unassigned
Resolution: Fixed Votes: 0
Labels: None

Attachments: Text File crash-2016-09-10_09.15.27-server.txt     Text File crash-2016-09-25_19.41.45-server.txt     Text File crash-2016-09-25_19.41.49-server.txt    

 Description   

At line 158 in ChunkRegionLoader there is the code

if (this.b.isEmpty())

{ // Do stuff }

else
ChunkCoordIntPair chunkcoordintpair = (ChunkCoordIntPair) this.b.keySet().iterator().next();

The problem is that 'b' is a concurrent hashmap, and its possible for the map to return false for the isEmpty() check, but the entry is removed which then throws an not found error when it attempts to iterate a few milliseconds later.

This has happened to me, and when it does happen. It kills the entire file saving thread.

I only found out about this because someone complained that their world was no longer saving and they lost all their work.

 Comments   
Comment by pokechu22 [ 26/Sep/16 ]

NOT FIXED. I managed to get the server to crash, including the double crash report found in MC-106551, after running a bot on my test server that ran /save-all flush over 20 times per minute for about a week straight. I wasn't running the most recent version (I was running 8788b79a48a) but it was still a version including the patch that was supposed to fix the issue.

Here's the double crash report: crash-2016-09-25_19.41.45-server.txt (Watching Server) and crash-2016-09-25_19.41.49-server.txt (Exception ticking world).

And here's the last few lines of the log file:

[19:41:16] [Server thread/INFO]: TestBot issued server command: /fill ~-64 ~-1 ~-64 ~64 ~-1 ~64 minecraft:stained_hardened_clay 14
[19:41:16] [Server thread/INFO]: [TestBot: 16641 blocks filled]
[19:41:18] [Server thread/INFO]: TestBot issued server command: /save-all flush
[19:41:19] [File IO Thread/INFO]: ThreadedAnvilChunkStorage (world): All chunks are saved
[19:41:19] [Server thread/INFO]: ThreadedAnvilChunkStorage (world): All chunks are saved
[19:41:19] [Server thread/INFO]: ThreadedAnvilChunkStorage (DIM-1): All chunks are saved
[19:41:19] [Server thread/INFO]: ThreadedAnvilChunkStorage (DIM1): All chunks are saved
[19:41:19] [Server thread/INFO]: [TestBot: Saved the world]
[19:41:19] [Server thread/INFO]: TestBot issued server command: /fill ~-64 ~-1 ~-64 ~64 ~-1 ~64 minecraft:stained_hardened_clay 11
[19:41:19] [Server thread/INFO]: [TestBot: 16641 blocks filled]
[19:41:21] [Server thread/INFO]: TestBot issued server command: /save-all flush
[19:41:24] [Server thread/INFO]: ThreadedAnvilChunkStorage (world): All chunks are saved
[19:41:24] [Server thread/INFO]: ThreadedAnvilChunkStorage (DIM-1): All chunks are saved
[19:41:24] [Server thread/INFO]: ThreadedAnvilChunkStorage (DIM1): All chunks are saved
[19:41:24] [Server thread/INFO]: [TestBot: Saved the world]
[19:41:25] [Server thread/INFO]: TestBot issued server command: /fill ~-64 ~-1 ~-64 ~64 ~-1 ~64 minecraft:stained_hardened_clay 14
[19:41:25] [Server thread/INFO]: [TestBot: 16641 blocks filled]
[19:41:27] [Server thread/INFO]: TestBot issued server command: /save-all flush
[19:41:30] [Server thread/INFO]: ThreadedAnvilChunkStorage (world): All chunks are saved
[19:41:30] [Server thread/INFO]: ThreadedAnvilChunkStorage (DIM-1): All chunks are saved
[19:41:30] [Server thread/INFO]: ThreadedAnvilChunkStorage (DIM1): All chunks are saved
[19:41:30] [Server thread/INFO]: [TestBot: Saved the world]
[19:41:34] [Server thread/INFO]: TestBot issued server command: /fill ~-64 ~-1 ~-64 ~64 ~-1 ~64 minecraft:stained_hardened_clay 11
[19:41:34] [Server thread/INFO]: [TestBot: 16641 blocks filled]
[19:41:36] [Server thread/INFO]: TestBot issued server command: /save-all flush
[19:41:45] [Server Watchdog/FATAL]: A single server tick took 60.00 seconds (should be max 0.05)
[19:41:45] [Server Watchdog/FATAL]: Considering it to be crashed, server will forcibly shutdown.
[19:41:45] [Server Watchdog/ERROR]: This crash report has been saved to: C:\pokechu22\TestServer_1.10_MC-106551\.\crash-reports\crash-2016-09-25_19.41.45-server.txt
[19:41:45] [Thread-3/INFO]: Stopping server
[19:41:46] [Thread-3/INFO]: Saving players
Comment by pokechu22 [ 13/Sep/16 ]

I've run the bot for several days straight now and there have been no crashes on CraftBukkit version git-Bukkit-8788b79 (MC: 1.10.2) (Implementing API version 1.10.2-R0.1-SNAPSHOT). So I can say that either the fix has worked completely, or it's been fixed to the point where it's not going to happen in practice.

However, I will note that the finished saving message still sometimes is printed from two threads:

[00:00:11] [Server thread/INFO]: TestBot issued server command: /save-all flush
[00:00:12] [File IO Thread/INFO]: ThreadedAnvilChunkStorage (world): All chunks are saved
[00:00:12] [Server thread/INFO]: ThreadedAnvilChunkStorage (world): All chunks are saved
[00:00:12] [Server thread/INFO]: ThreadedAnvilChunkStorage (DIM-1): All chunks are saved
[00:00:12] [Server thread/INFO]: ThreadedAnvilChunkStorage (DIM1): All chunks are saved
[00:00:12] [Server thread/INFO]: [TestBot: Saved the world]

or sometimes

[00:12:32] [Server thread/INFO]: TestBot issued server command: /save-all flush
[00:12:32] [Server thread/INFO]: ThreadedAnvilChunkStorage (world): All chunks are saved
[00:12:32] [Server thread/INFO]: ThreadedAnvilChunkStorage (DIM-1): All chunks are saved
[00:12:32] [Server thread/INFO]: ThreadedAnvilChunkStorage (DIM1): All chunks are saved
[00:12:32] [File IO Thread/INFO]: ThreadedAnvilChunkStorage (world): All chunks are saved
[00:12:32] [Server thread/INFO]: [TestBot: Saved the world]

or sometimes, extremely rarely,

[05:37:27] [Server thread/INFO]: TestBot issued server command: /save-all flush
[05:37:28] [Server thread/INFO]: ThreadedAnvilChunkStorage (world): All chunks are saved
[05:37:28] [Server thread/INFO]: ThreadedAnvilChunkStorage (DIM-1): All chunks are saved
[05:37:28] [Server thread/INFO]: ThreadedAnvilChunkStorage (DIM1): All chunks are saved
[05:37:28] [Server thread/INFO]: [TestBot: Saved the world]
[05:37:28] [File IO Thread/INFO]: ThreadedAnvilChunkStorage (world): All chunks are saved

This is a related, but probably separate vanilla issue but still one to keep in mind.

Comment by pokechu22 [ 10/Sep/16 ]

Attempted to reproduce this in the latest build with a bot for 9 hours; it did not happen there.

I also retried the build before this was fixed, and did get it to happen within about 30 minutes, with "An unknown error occurred while attempting to perform this command":

[08:11:12] [Server thread/INFO]: TestBot issued server command: /save-all flush
[08:11:12] [Server thread/WARN]: Unknown CommandBlock failed to handle command
java.util.NoSuchElementException
 at java.util.concurrent.ConcurrentHashMap$KeyIterator.next(ConcurrentHashMap.java:3416) ~[?:1.8.0_92]
 at net.minecraft.server.v1_10_R1.ChunkRegionLoader.c(ChunkRegionLoader.java:156) ~[2f5bda8-craftbukkit-1.10.2-R0.1-SNAPSHOT.jar:git-Bukkit-2f5bda8]
 at net.minecraft.server.v1_10_R1.ChunkRegionLoader.b(ChunkRegionLoader.java:201) ~[2f5bda8-craftbukkit-1.10.2-R0.1-SNAPSHOT.jar:git-Bukkit-2f5bda8]
 at net.minecraft.server.v1_10_R1.ChunkProviderServer.c(ChunkProviderServer.java:242) ~[2f5bda8-craftbukkit-1.10.2-R0.1-SNAPSHOT.jar:git-Bukkit-2f5bda8]
 at net.minecraft.server.v1_10_R1.WorldServer.flushSave(WorldServer.java:1018) ~[2f5bda8-craftbukkit-1.10.2-R0.1-SNAPSHOT.jar:git-Bukkit-2f5bda8]
 at net.minecraft.server.v1_10_R1.CommandSaveAll.execute(SourceFile:47) ~[2f5bda8-craftbukkit-1.10.2-R0.1-SNAPSHOT.jar:git-Bukkit-2f5bda8]
 at org.bukkit.craftbukkit.v1_10_R1.command.VanillaCommandWrapper.dispatchVanillaCommand(VanillaCommandWrapper.java:102) [2f5bda8-craftbukkit-1.10.2-R0.1-SNAPSHOT.jar:git-Bukkit-2f5bda8]
 at org.bukkit.craftbukkit.v1_10_R1.command.VanillaCommandWrapper.execute(VanillaCommandWrapper.java:37) [2f5bda8-craftbukkit-1.10.2-R0.1-SNAPSHOT.jar:git-Bukkit-2f5bda8]
 at org.bukkit.command.SimpleCommandMap.dispatch(SimpleCommandMap.java:140) [2f5bda8-craftbukkit-1.10.2-R0.1-SNAPSHOT.jar:git-Bukkit-2f5bda8]
 at org.bukkit.craftbukkit.v1_10_R1.CraftServer.dispatchCommand(CraftServer.java:626) [2f5bda8-craftbukkit-1.10.2-R0.1-SNAPSHOT.jar:git-Bukkit-2f5bda8]
 at net.minecraft.server.v1_10_R1.PlayerConnection.handleCommand(PlayerConnection.java:1299) [2f5bda8-craftbukkit-1.10.2-R0.1-SNAPSHOT.jar:git-Bukkit-2f5bda8]
 at net.minecraft.server.v1_10_R1.PlayerConnection.a(PlayerConnection.java:1159) [2f5bda8-craftbukkit-1.10.2-R0.1-SNAPSHOT.jar:git-Bukkit-2f5bda8]
 at net.minecraft.server.v1_10_R1.PacketPlayInChat.a(SourceFile:37) [2f5bda8-craftbukkit-1.10.2-R0.1-SNAPSHOT.jar:git-Bukkit-2f5bda8]
 at net.minecraft.server.v1_10_R1.PacketPlayInChat.a(SourceFile:9) [2f5bda8-craftbukkit-1.10.2-R0.1-SNAPSHOT.jar:git-Bukkit-2f5bda8]
 at net.minecraft.server.v1_10_R1.PlayerConnectionUtils$1.run(SourceFile:13) [2f5bda8-craftbukkit-1.10.2-R0.1-SNAPSHOT.jar:git-Bukkit-2f5bda8]
 at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_92]
 at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_92]
 at net.minecraft.server.v1_10_R1.SystemUtils.a(SourceFile:45) [2f5bda8-craftbukkit-1.10.2-R0.1-SNAPSHOT.jar:git-Bukkit-2f5bda8]
 at net.minecraft.server.v1_10_R1.MinecraftServer.D(MinecraftServer.java:688) [2f5bda8-craftbukkit-1.10.2-R0.1-SNAPSHOT.jar:git-Bukkit-2f5bda8]
 at net.minecraft.server.v1_10_R1.DedicatedServer.D(DedicatedServer.java:361) [2f5bda8-craftbukkit-1.10.2-R0.1-SNAPSHOT.jar:git-Bukkit-2f5bda8]
 at net.minecraft.server.v1_10_R1.MinecraftServer.C(MinecraftServer.java:643) [2f5bda8-craftbukkit-1.10.2-R0.1-SNAPSHOT.jar:git-Bukkit-2f5bda8]
 at net.minecraft.server.v1_10_R1.MinecraftServer.run(MinecraftServer.java:547) [2f5bda8-craftbukkit-1.10.2-R0.1-SNAPSHOT.jar:git-Bukkit-2f5bda8]
 at java.lang.Thread.run(Thread.java:745) [?:1.8.0_92]

This did not crash the server, so I'm running the bot some more. I've also seen

[09:13:13] [File IO Thread/WARN]: Exception in thread "File IO Thread" 
[09:13:13] [File IO Thread/WARN]: java.util.NoSuchElementException
[09:13:13] [File IO Thread/WARN]:  at java.util.concurrent.ConcurrentHashMap$KeyIterator.next(ConcurrentHashMap.java:3416)
[09:13:13] [File IO Thread/WARN]:  at net.minecraft.server.v1_10_R1.ChunkRegionLoader.c(ChunkRegionLoader.java:156)
[09:13:13] [File IO Thread/WARN]:  at net.minecraft.server.v1_10_R1.FileIOThread.c(SourceFile:37)
[09:13:13] [File IO Thread/WARN]:  at net.minecraft.server.v1_10_R1.FileIOThread.run(SourceFile:30)
[09:13:13] [File IO Thread/WARN]:  at java.lang.Thread.run(Thread.java:745)

but that did not generate a command error message or crash the server.

Finally, I received the same deadlock twice (same stacktrace), see crash-2016-09-10_09.15.27-server.txt.

REMEMBER: this is all with the out-of-date version, to check and see what crashes this issue would have caused in the past. I have not had the most recent version crash from my bot yet (though it's still possible that it might).

Comment by md_5 [ 27/Aug/16 ]

https://bugs.mojang.com/browse/MC-106551

PS: This can only occur on a clean install when using /save-all flush which is unnecessary anyway

Comment by pokechu22 [ 27/Aug/16 ]

Completely slipped my mind that spigot wouldn't be patching this bug.

Spigot/craftbukkit does sometimes patch bugs like this and other vanilla crashes, but it's still always a good idea to make a ticket for vanilla as well so that it gets fixed on the main game.

Comment by libraryaddict [ 27/Aug/16 ]

Ah right, it would be vanilla. My bad. Completely slipped my mind that spigot wouldn't be patching this bug.

Comment by pokechu22 [ 27/Aug/16 ]

This sounds like it is a vanilla issue - see if it can be reproduced on a vanilla server. Also, can you post the stacktrace, please? It'd let me search for reports of this on the vanilla server via hopper (though I'd have to process it to get it to the vanilla obfuscation, I can do so).

Generated at Thu Mar 27 18:55:25 UTC 2025 using Jira 10.3.3#10030003-sha1:d220e3fefc8dfc6d47f522d3b9a20c1455e12b7b.