Server suddenly deadlocks
JoJoDeveloping opened this issue · 12 comments
Hello,
I just encountered a server hang that might be related to AE2, although I am not sure what would have caused it. I only suspect AE2 because you guys show up in the server stack trace dump, but again that might be unrelated. Basically, I was doing something not strictly related to AE2 when I noticed that the server thread had stopped working, -- i.e. the world stopped updating, chat did no longer work, etc. I had to kill minecraft.
Here is the stacktrace of the server thread. I have also taken a thread dump before killing if that would be of help:
"Server thread" #2507 prio=5 os_prio=0 cpu=565976.45ms elapsed=9233.99s tid=0x00007f5170265000 nid=0x12c5b waiting on condition [0x00007f51a57fe000]
java.lang.Thread.State: WAITING (parking)
at jdk.internal.misc.Unsafe.park([email protected]/Native Method)
- parking to wait for <0x0000000681c74040> (a java.util.concurrent.CompletableFuture$Signaller)
at java.util.concurrent.locks.LockSupport.park([email protected]/LockSupport.java:211)
at java.util.concurrent.CompletableFuture$Signaller.block([email protected]/CompletableFuture.java:1860)
at java.util.concurrent.ForkJoinPool.managedBlock([email protected]/ForkJoinPool.java:3137)
at java.util.concurrent.CompletableFuture.waitingGet([email protected]/CompletableFuture.java:1887)
at java.util.concurrent.CompletableFuture.join([email protected]/CompletableFuture.java:2107)
at net.minecraft.world.server.ServerChunkProvider.func_212849_a_(SourceFile:124)
at net.minecraft.world.World.func_217353_a(World.java:167)
at net.minecraft.world.IWorldReader.func_217348_a(IWorldReader.java:112)
at net.minecraft.world.World.func_212866_a_(World.java:163)
at net.minecraft.world.World.func_180495_p(World.java:379)
at net.minecraft.tileentity.TileEntity.func_70296_d(TileEntity.java:102)
at appeng.tile.AEBaseTileEntity.markDirtyAtEndOfTick(AEBaseTileEntity.java:443)
at appeng.tile.AEBaseTileEntity$$Lambda$26242/0x0000000803e1b440.call(Unknown Source)
at appeng.hooks.TickHandler.processQueue(TickHandler.java:269)
at appeng.hooks.TickHandler.onServerTick(TickHandler.java:237)
at appeng.hooks.TickHandler$$Lambda$11976/0x00000008021d0c40.accept(Unknown Source)
at net.minecraftforge.eventbus.EventBus.doCastFilter(EventBus.java:247)
at net.minecraftforge.eventbus.EventBus.lambda$addListener$11(EventBus.java:239)
at net.minecraftforge.eventbus.EventBus$$Lambda$3111/0x0000000800be4840.invoke(Unknown Source)
at net.minecraftforge.eventbus.EventBus.post(EventBus.java:297)
at net.minecraftforge.fml.hooks.BasicEventHooks.onPostServerTick(BasicEventHooks.java:120)
at net.minecraft.server.MinecraftServer.func_71217_p(MinecraftServer.java:827)
at net.minecraft.server.integrated.IntegratedServer.func_71217_p(IntegratedServer.java:78)
at net.minecraft.server.MinecraftServer.func_240802_v_(MinecraftServer.java:641)
at net.minecraft.server.MinecraftServer.lambda$startServer$0(MinecraftServer.java:232)
at net.minecraft.server.MinecraftServer$$Lambda$24731/0x0000000803b53440.run(Unknown Source)
at java.lang.Thread.run([email protected]/Thread.java:832)
Is this an AE2 bug? If yes, how can I help you? If not, do you have any idea where I could search for the culprit?
Check your debug log for earlier problems. This can be caused by worldgen crashing or other threads trying to access the world concurrently.
This is the last few (dozen) lines from the debug.log. The server stopped being responsive around 23:35-23:40. I can't see any crashing of any worldgen thread (also I was not exploring new regions during the crash). There are no stack-traces in the debug log except for some thrown during world load a few hours (!) earlier.
[27Dec2020 22:32:33.332] [Server thread/INFO] [FTB Utilities Backups/]: Server Backup started!
[27Dec2020 22:32:33.333] [Server thread/INFO] [net.minecraft.server.MinecraftServer/]: Server Backup started!
[27Dec2020 22:32:33.409] [Thread-392/INFO] [FTB Utilities Backups/]: Deleting old backup: 2020-12-21-23-34-02.zip
[27Dec2020 22:32:33.411] [Thread-392/INFO] [FTB Utilities Backups/]: Backing up 329 files...
[27Dec2020 22:32:33.416] [Thread-392/INFO] [FTB Utilities Backups/]: Compressing 329 files...
[27Dec2020 22:32:38.140] [Render thread/DEBUG] [se.mickelus.tetra.items.modular.ModularItem/]: Gathering properties for Iron Axe (8c8e4c41-b8c5-4548-9283-7aed244b542d)
[27Dec2020 22:32:38.153] [Render thread/DEBUG] [se.mickelus.tetra.items.modular.ModularItem/]: Gathering properties for Blackstone Hammer (49c85df5-49a2-4470-8565-97bbc442c59c)
[27Dec2020 22:32:42.317] [Render thread/DEBUG] [se.mickelus.tetra.items.modular.impl.ModularDoubleHeadedItem/]: Gathering tool data for Diamond Pickaxe (474c9dd3-3864-4b92-8fba-5e2c3f983468)
[27Dec2020 22:32:42.404] [Server thread/DEBUG] [se.mickelus.tetra.items.modular.ModularItem/]: Gathering attribute modifiers for Diamond Pickaxe (474c9dd3-3864-4b92-8fba-5e2c3f983468)
[27Dec2020 22:32:43.252] [Render thread/DEBUG] [se.mickelus.tetra.items.modular.ModularItem/]: Gathering effect data for Diamond Pickaxe (474c9dd3-3864-4b92-8fba-5e2c3f983468)
[27Dec2020 22:32:47.645] [Render thread/DEBUG] [se.mickelus.tetra.items.modular.ModularItem/]: Gathering tool data for Diamond Shortblade (d4ce3692-d583-41db-ae57-b97b4e2a12d2)
[27Dec2020 22:32:47.650] [Server thread/DEBUG] [se.mickelus.tetra.items.modular.ModularItem/]: Gathering attribute modifiers for Diamond Shortblade (d4ce3692-d583-41db-ae57-b97b4e2a12d2)
[27Dec2020 22:32:47.651] [Server thread/DEBUG] [se.mickelus.tetra.items.modular.ModularItem/]: Gathering effect data for Diamond Shortblade (d4ce3692-d583-41db-ae57-b97b4e2a12d2)
[27Dec2020 22:32:48.065] [Thread-392/INFO] [FTB Utilities Backups/]: Done compressing in 00:14 seconds (354.6MB)!
[27Dec2020 22:32:48.072] [Thread-392/INFO] [FTB Utilities Backups/]: Created /mnt/workfs/johannes/Minecraft/Modpacks/FTBA/instances/feea1405-40c7-4b11-a6c0-6931da96debe/backups/2020-12-27-22-32-33.zip from /mnt/workfs/johannes/Minecraft/Modpacks/FTBA/instances/feea1405-40c7-4b11-a6c0-6931da96debe/saves/New World
[27Dec2020 22:32:48.119] [Thread-392/INFO] [net.minecraft.server.MinecraftServer/]: Server backup done in 00:14! (354.6MB | 3.0GB)
[27Dec2020 22:32:48.128] [Render thread/INFO] [net.minecraft.client.gui.NewChatGui/]: [CHAT] Server backup done in 00:14! (354.6MB | 3.0GB)
[27Dec2020 22:33:15.044] [Render thread/DEBUG] [se.mickelus.tetra.items.modular.ModularItem/]: Gathering attribute modifiers for Blackstone Hammer (49c85df5-49a2-4470-8565-97bbc442c59c)
[27Dec2020 22:33:31.439] [Server thread/INFO] [net.minecraft.server.MinecraftServer/]: JoJoModding has reached the goal [Balanced Crafting System]
[27Dec2020 22:33:31.442] [Render thread/INFO] [net.minecraft.client.gui.NewChatGui/]: [CHAT] JoJoModding has reached the goal [Balanced Crafting System]
[27Dec2020 22:33:31.536] [Render thread/INFO] [net.minecraft.advancements.AdvancementList/]: Loaded 1761 advancements
[27Dec2020 22:33:38.604] [Server thread/DEBUG] [net.minecraftforge.fml.FMLWorldPersistenceHook/WP]: Gathering id map for writing to world save New World
[27Dec2020 22:33:38.624] [Server thread/DEBUG] [net.minecraftforge.fml.FMLWorldPersistenceHook/WP]: ID Map collection complete New World
[27Dec2020 22:34:15.114] [Render thread/DEBUG] [se.mickelus.tetra.items.modular.ModularItem/]: Gathering properties for Diamond Pickaxe (474c9dd3-3864-4b92-8fba-5e2c3f983468)
[27Dec2020 22:34:15.131] [Render thread/DEBUG] [se.mickelus.tetra.items.modular.ModularItem/]: Gathering properties for Diamond Shortblade (d4ce3692-d583-41db-ae57-b97b4e2a12d2)
[27Dec2020 22:37:42.331] [Render thread/DEBUG] [se.mickelus.tetra.items.modular.impl.ModularDoubleHeadedItem/]: Gathering tool data for Diamond Pickaxe (474c9dd3-3864-4b92-8fba-5e2c3f983468)
[27Dec2020 22:37:42.457] [Server thread/DEBUG] [se.mickelus.tetra.items.modular.ModularItem/]: Gathering attribute modifiers for Diamond Pickaxe (474c9dd3-3864-4b92-8fba-5e2c3f983468)
[27Dec2020 22:37:43.290] [Render thread/DEBUG] [se.mickelus.tetra.items.modular.ModularItem/]: Gathering effect data for Diamond Pickaxe (474c9dd3-3864-4b92-8fba-5e2c3f983468)
[27Dec2020 22:38:33.154] [Render thread/DEBUG] [se.mickelus.tetra.items.modular.ModularItem/]: Gathering tool data for Diamond Shortblade (d4ce3692-d583-41db-ae57-b97b4e2a12d2)
[27Dec2020 22:38:33.202] [Server thread/DEBUG] [se.mickelus.tetra.items.modular.ModularItem/]: Gathering attribute modifiers for Diamond Shortblade (d4ce3692-d583-41db-ae57-b97b4e2a12d2)
[27Dec2020 22:38:33.203] [Server thread/DEBUG] [se.mickelus.tetra.items.modular.ModularItem/]: Gathering effect data for Diamond Shortblade (d4ce3692-d583-41db-ae57-b97b4e2a12d2)
[27Dec2020 22:38:38.551] [Server thread/DEBUG] [net.minecraftforge.fml.FMLWorldPersistenceHook/WP]: Gathering id map for writing to world save New World
[27Dec2020 22:38:38.567] [Server thread/DEBUG] [net.minecraftforge.fml.FMLWorldPersistenceHook/WP]: ID Map collection complete New World
[27Dec2020 22:39:14.566] [Render thread/DEBUG] [se.mickelus.tetra.items.modular.ModularItem/]: Gathering properties for Iron Axe (8c8e4c41-b8c5-4548-9283-7aed244b542d)
[27Dec2020 22:39:14.573] [Render thread/DEBUG] [se.mickelus.tetra.items.modular.ModularItem/]: Gathering properties for Blackstone Hammer (49c85df5-49a2-4470-8565-97bbc442c59c)
[27Dec2020 22:39:15.118] [Render thread/DEBUG] [se.mickelus.tetra.items.modular.ModularItem/]: Gathering properties for Diamond Pickaxe (474c9dd3-3864-4b92-8fba-5e2c3f983468)
[27Dec2020 22:39:15.134] [Render thread/DEBUG] [se.mickelus.tetra.items.modular.ModularItem/]: Gathering properties for Diamond Shortblade (d4ce3692-d583-41db-ae57-b97b4e2a12d2)
[27Dec2020 22:39:56.192] [Render thread/DEBUG] [cpw.mods.inventorysorter.InventorySorter/]: Skipping action handling for blacklisted slot
[27Dec2020 22:42:42.368] [Render thread/DEBUG] [se.mickelus.tetra.items.modular.impl.ModularDoubleHeadedItem/]: Gathering tool data for Diamond Pickaxe (474c9dd3-3864-4b92-8fba-5e2c3f983468)
[27Dec2020 22:44:15.130] [Render thread/DEBUG] [se.mickelus.tetra.items.modular.ModularItem/]: Gathering properties for Diamond Pickaxe (474c9dd3-3864-4b92-8fba-5e2c3f983468)
[27Dec2020 22:44:15.167] [Render thread/DEBUG] [se.mickelus.tetra.items.modular.ModularItem/]: Gathering properties for Diamond Shortblade (d4ce3692-d583-41db-ae57-b97b4e2a12d2)
[27Dec2020 22:47:42.408] [Render thread/DEBUG] [se.mickelus.tetra.items.modular.impl.ModularDoubleHeadedItem/]: Gathering tool data for Diamond Pickaxe (474c9dd3-3864-4b92-8fba-5e2c3f983468)
[27Dec2020 22:49:15.139] [Render thread/DEBUG] [se.mickelus.tetra.items.modular.ModularItem/]: Gathering properties for Diamond Pickaxe (474c9dd3-3864-4b92-8fba-5e2c3f983468)
[27Dec2020 22:49:15.171] [Render thread/DEBUG] [se.mickelus.tetra.items.modular.ModularItem/]: Gathering properties for Diamond Shortblade (d4ce3692-d583-41db-ae57-b97b4e2a12d2)
[27Dec2020 22:49:30.681] [pool-5-thread-690/INFO] [STDOUT/]: [net.creeperhost.minetogether.irc.IrcHandler:sendString:119]: Exception: java.net.SocketException: Socket closed
[27Dec2020 22:49:30.681] [pool-5-thread-691/INFO] [STDOUT/]: [net.creeperhost.minetogether.irc.IrcHandler:sendString:119]: Exception: java.net.SocketException: Socket closed
[27Dec2020 22:49:30.681] [pool-5-thread-693/INFO] [STDOUT/]: [net.creeperhost.minetogether.irc.IrcHandler:sendString:119]: Exception: java.net.SocketException: Socket closed
[27Dec2020 22:49:30.689] [pool-5-thread-687/INFO] [STDOUT/]: [net.creeperhost.minetogether.irc.IrcHandler:sendString:119]: Exception: java.net.SocketException: Socket closed
[27Dec2020 22:49:30.691] [pool-5-thread-684/INFO] [STDOUT/]: [net.creeperhost.minetogether.irc.IrcHandler:sendString:119]: Exception: java.net.SocketException: Socket closed
[27Dec2020 22:49:30.823] [pool-5-thread-686/INFO] [STDOUT/]: [net.creeperhost.minetogether.irc.IrcHandler:sendString:119]: Exception: java.net.SocketException: Socket closed
[27Dec2020 22:49:30.811] [pool-5-thread-683/INFO] [STDOUT/]: [net.creeperhost.minetogether.irc.IrcHandler:sendString:119]: Exception: java.net.SocketException: Socket closed
[27Dec2020 22:49:30.960] [pool-5-thread-689/INFO] [STDOUT/]: [net.creeperhost.minetogether.irc.IrcHandler:sendString:119]: Exception: java.net.SocketException: Socket closed
[27Dec2020 22:49:31.187] [pool-5-thread-685/INFO] [STDOUT/]: [net.creeperhost.minetogether.irc.IrcHandler:sendString:119]: Exception: java.net.SocketException: Socket closed
[27Dec2020 22:49:31.699] [pool-5-thread-688/INFO] [STDOUT/]: [net.creeperhost.minetogether.irc.IrcHandler:sendString:119]: Exception: java.net.SocketException: Socket closed
[27Dec2020 22:49:34.566] [pool-5-thread-692/INFO] [STDOUT/]: [net.creeperhost.minetogether.irc.IrcHandler:sendString:119]: Exception: java.net.SocketException: Socket closed
[27Dec2020 22:52:42.456] [Render thread/DEBUG] [se.mickelus.tetra.items.modular.impl.ModularDoubleHeadedItem/]: Gathering tool data for Diamond Pickaxe (474c9dd3-3864-4b92-8fba-5e2c3f983468)
I'm having a similar issue. https://paste.gg/p/anonymous/e79637ed213242838f3d797d7e7aa40c the last thing that says error says something about this mod, it prevents me from rendering new chunks, preventing me from switching game modes, never completes "Saving World", and probably many more issues that i haven't encountered yet
I can concur, I am experiencing these issues too. Sometimes I can load nearby chunks via specific getChunk() calls to see that these are occurring around the meteors. Cannot fly near or load these chunks with getChunk() without causing a deadlock. I'm trying to see if I can get a stacktrace of the generator to see what's causing these chunks to get held up.
Pack: DW20 1.16.4 1.2.0
Level Seed: 2592
Coordinates 1: -3552 128 -2416
Coordinates 2: -272 128 -1936 (Can be generated if a player flies into view, will crash if direct TP)
This server will crash on a server, will crash if the world is copied to single player, and crash at the same coordinates when the world is generated purely by the client.
Here is an attached sampler, threaddump, and images showing some kind of crater at these locations. I'm currently generating a 20kx20k world and will provide more data if I find another troublesome crater.
If you have a better way to debug this please let me know.
https://drive.google.com/drive/folders/1zN9vIF84mrUG7KZUEt-GNx3JP_DCNXU2?usp=sharing
So, debugging DW20 directly (which is a pain in the ass), this is indeed a chunk lighting thread crashing, which MC does not handle.
Given that the Meteorite spawning works locally, and I don't know if DW20 has any mods affecting chunk lighting. There's not a ton I can do.
Pack has been updated to DW20-1.16.4 v1.3.1
Found another bad chunk 591,-257 @ ~9456, 128, -4112 on the same seed as before. Chunk also contains an AE2 crater.
I'll update our server and visit these chunks again. I appreciate you looking into this. And glad I could get you a reproducible situation.
Okay, I actually reproduced this in dev by placing a glowstone block at y=255 (so, in an otherwise empty chunk-section) and then immediately replacing it with air again. This leads to the same crash/deadlock.
The root cause - as it turns out - is a bug in Vanilla's world-gen lighting update. During world-gen they collect a list with all positions that contain emissive blocks (glowstone, lava, etc.), and after world-generation they try to do light-propagation for each of these positions, while making the assumption that the block is still present.
Since we delete large sections of a chunk, we end up clearing out entire chunk sections, which completely remove these from the lighting engine. If those sections contained any emissive block, the post-worldgen light-update will crash.
I've cooked up a Mixin to fix this particular problem by skipping any light updates for blocks that are no longer emissive.
See: c180161