IllegalStateException: Asynchronous preparation of chunk data for async save!

[mibby]

Issue Description: Dynmap errors on shutdown if it is actively rendering / saving tiles.

• Dynmap Version: dynmap version 3.4-819

• Server Version: git-Purpur-1752 (Paper 1.19.2)

• Pastebin of Configuration.txt: https://paste.gg/p/anonymous/84efb69a60124fe8b884a427bd745959/files/d92f9ce23d4d44c9adac79751491cc78/raw

• Server Host (if applicable): Selfhosted

• Pastebin of crashlogs or other relevant logs: https://paste.gg/p/anonymous/589ea0998bd846d7ad1017f5182c0a33/files/7cbd3245509949f3914ee68f68332974/raw

• Steps to Replicate:

  • Generate new chunks and have dynmap queue up a backlog of tiles to render.
  • Shut down server to restart it.
  • See errors during shutdown.

[02:56:02] [Dynmap Render Thread/ERROR]: Thread Dynmap Render Thread failed main thread check: preparation of chunk data for async save
java.lang.Throwable: null
	at org.spigotmc.AsyncCatcher.catchOp(AsyncCatcher.java:15) ~[purpur-1.19.2.jar:git-Purpur-1752]
	at net.minecraft.world.level.chunk.storage.ChunkSerializer.getAsyncSaveData(ChunkSerializer.java:465) ~[?:?]
	at jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:577) ~[?:?]
	at org.dynmap.bukkit.helper.v119.AsyncChunkProvider119.lambda$getLoadedChunk$6(AsyncChunkProvider119.java:96) ~[Dynmap-HEAD-spigot.jar:?]
	at java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1768) ~[?:?]
	at net.minecraft.util.thread.BlockableEventLoop.execute(BlockableEventLoop.java:100) ~[?:?]
	at java.util.concurrent.CompletableFuture.asyncSupplyStage(CompletableFuture.java:1782) ~[?:?]
	at java.util.concurrent.CompletableFuture.supplyAsync(CompletableFuture.java:2005) ~[?:?]
	at org.dynmap.bukkit.helper.v119.AsyncChunkProvider119.getLoadedChunk(AsyncChunkProvider119.java:94) ~[Dynmap-HEAD-spigot.jar:?]
	at org.dynmap.bukkit.helper.v119.MapChunkCache119.getLoadedChunkAsync(MapChunkCache119.java:40) ~[Dynmap-HEAD-spigot.jar:?]
	at org.dynmap.common.chunk.GenericMapChunkCache.getLoadedChunksAsync(GenericMapChunkCache.java:803) ~[Dynmap-HEAD-spigot.jar:?]
	at org.dynmap.common.chunk.GenericMapChunkCache.loadChunksAsync(GenericMapChunkCache.java:844) ~[Dynmap-HEAD-spigot.jar:?]
	at org.dynmap.bukkit.DynmapPlugin$BukkitServer.createMapChunkCache(DynmapPlugin.java:570) ~[Dynmap-HEAD-spigot.jar:?]
	at org.dynmap.MapManager$FullWorldRenderState.processTile(MapManager.java:767) ~[Dynmap-HEAD-spigot.jar:?]
	at org.dynmap.MapManager$FullWorldRenderState.run(MapManager.java:726) ~[Dynmap-HEAD-spigot.jar:?]
	at org.dynmap.MapManager$DynmapScheduledThreadPoolExecutor$1.run(MapManager.java:234) ~[Dynmap-HEAD-spigot.jar:?]
	at org.dynmap.MapManager$DynmapScheduledThreadPoolExecutor$2.run(MapManager.java:252) ~[Dynmap-HEAD-spigot.jar:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) ~[?:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) ~[?:?]
	at java.lang.Thread.run(Thread.java:833) ~[?:?]
[02:56:02] [Dynmap Render Thread/ERROR]: [dynmap] Exception during render job: world=world, map=null
[02:56:02] [Dynmap Render Thread/WARN]: java.lang.RuntimeException: java.util.concurrent.ExecutionException: java.lang.RuntimeException: java.lang.reflect.InvocationTargetException
[02:56:02] [Dynmap Render Thread/WARN]: 	at Dynmap-HEAD-spigot.jar//org.dynmap.bukkit.helper.v119.AsyncChunkProvider119.lambda$getLoadedChunk$7(AsyncChunkProvider119.java:114)
[02:56:02] [Dynmap Render Thread/WARN]: 	at Dynmap-HEAD-spigot.jar//org.dynmap.bukkit.helper.v119.MapChunkCache119.lambda$getLoadedChunkAsync$0(MapChunkCache119.java:42)
[02:56:02] [Dynmap Render Thread/WARN]: 	at Dynmap-HEAD-spigot.jar//org.dynmap.common.chunk.GenericMapChunkCache.lambda$getLoadedChunksAsync$1(GenericMapChunkCache.java:829)
[02:56:02] [Dynmap Render Thread/WARN]: 	at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
[02:56:02] [Dynmap Render Thread/WARN]: 	at Dynmap-HEAD-spigot.jar//org.dynmap.common.chunk.GenericMapChunkCache.getLoadedChunksAsync(GenericMapChunkCache.java:827)
[02:56:02] [Dynmap Render Thread/WARN]: 	at Dynmap-HEAD-spigot.jar//org.dynmap.common.chunk.GenericMapChunkCache.loadChunksAsync(GenericMapChunkCache.java:844)
[02:56:02] [Dynmap Render Thread/WARN]: 	at Dynmap-HEAD-spigot.jar//org.dynmap.bukkit.DynmapPlugin$BukkitServer.createMapChunkCache(DynmapPlugin.java:570)
[02:56:02] [Dynmap Render Thread/WARN]: 	at Dynmap-HEAD-spigot.jar//org.dynmap.MapManager$FullWorldRenderState.processTile(MapManager.java:767)
[02:56:02] [Dynmap Render Thread/WARN]: 	at Dynmap-HEAD-spigot.jar//org.dynmap.MapManager$FullWorldRenderState.run(MapManager.java:726)
[02:56:02] [Dynmap Render Thread/WARN]: 	at Dynmap-HEAD-spigot.jar//org.dynmap.MapManager$DynmapScheduledThreadPoolExecutor$1.run(MapManager.java:234)
[02:56:02] [Dynmap Render Thread/WARN]: 	at Dynmap-HEAD-spigot.jar//org.dynmap.MapManager$DynmapScheduledThreadPoolExecutor$2.run(MapManager.java:252)
[02:56:02] [Dynmap Render Thread/WARN]: 	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
[02:56:02] [Dynmap Render Thread/WARN]: 	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
[02:56:02] [Dynmap Render Thread/WARN]: 	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
[02:56:02] [Dynmap Render Thread/WARN]: 	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
[02:56:02] [Dynmap Render Thread/WARN]: 	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
[02:56:02] [Dynmap Render Thread/WARN]: 	at java.base/java.lang.Thread.run(Thread.java:833)
[02:56:02] [Dynmap Render Thread/WARN]: Caused by: java.util.concurrent.ExecutionException: java.lang.RuntimeException: java.lang.reflect.InvocationTargetException
[02:56:02] [Dynmap Render Thread/WARN]: 	at java.base/java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:396)
[02:56:02] [Dynmap Render Thread/WARN]: 	at java.base/java.util.concurrent.CompletableFuture.get(CompletableFuture.java:2073)
[02:56:02] [Dynmap Render Thread/WARN]: 	at Dynmap-HEAD-spigot.jar//org.dynmap.bukkit.helper.v119.AsyncChunkProvider119.lambda$getLoadedChunk$7(AsyncChunkProvider119.java:112)
[02:56:02] [Dynmap Render Thread/WARN]: 	... 16 more
[02:56:02] [Dynmap Render Thread/WARN]: Caused by: java.lang.RuntimeException: java.lang.reflect.InvocationTargetException
[02:56:02] [Dynmap Render Thread/WARN]: 	at Dynmap-HEAD-spigot.jar//org.dynmap.bukkit.helper.v119.AsyncChunkProvider119.lambda$getLoadedChunk$6(AsyncChunkProvider119.java:98)
[02:56:02] [Dynmap Render Thread/WARN]: 	at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1768)
[02:56:02] [Dynmap Render Thread/WARN]: 	at net.minecraft.util.thread.IAsyncTaskHandler.execute(IAsyncTaskHandler.java:100)
[02:56:02] [Dynmap Render Thread/WARN]: 	at java.base/java.util.concurrent.CompletableFuture.asyncSupplyStage(CompletableFuture.java:1782)
[02:56:02] [Dynmap Render Thread/WARN]: 	at java.base/java.util.concurrent.CompletableFuture.supplyAsync(CompletableFuture.java:2005)
[02:56:02] [Dynmap Render Thread/WARN]: 	at Dynmap-HEAD-spigot.jar//org.dynmap.bukkit.helper.v119.AsyncChunkProvider119.getLoadedChunk(AsyncChunkProvider119.java:94)
[02:56:02] [Dynmap Render Thread/WARN]: 	at Dynmap-HEAD-spigot.jar//org.dynmap.bukkit.helper.v119.MapChunkCache119.getLoadedChunkAsync(MapChunkCache119.java:40)
[02:56:02] [Dynmap Render Thread/WARN]: 	at Dynmap-HEAD-spigot.jar//org.dynmap.common.chunk.GenericMapChunkCache.getLoadedChunksAsync(GenericMapChunkCache.java:803)
[02:56:02] [Dynmap Render Thread/WARN]: 	... 12 more
[02:56:02] [Dynmap Render Thread/WARN]: Caused by: java.lang.reflect.InvocationTargetException
[02:56:02] [Dynmap Render Thread/WARN]: 	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:119)
[02:56:02] [Dynmap Render Thread/WARN]: 	at java.base/java.lang.reflect.Method.invoke(Method.java:577)
[02:56:02] [Dynmap Render Thread/WARN]: 	at Dynmap-HEAD-spigot.jar//org.dynmap.bukkit.helper.v119.AsyncChunkProvider119.lambda$getLoadedChunk$6(AsyncChunkProvider119.java:96)
[02:56:02] [Dynmap Render Thread/WARN]: 	... 19 more
[02:56:02] [Dynmap Render Thread/WARN]: Caused by: java.lang.IllegalStateException: Asynchronous preparation of chunk data for async save!
[02:56:02] [Dynmap Render Thread/WARN]: 	at org.spigotmc.AsyncCatcher.catchOp(AsyncCatcher.java:16)
[02:56:02] [Dynmap Render Thread/WARN]: 	at net.minecraft.world.level.chunk.storage.ChunkRegionLoader.getAsyncSaveData(ChunkRegionLoader.java:465)
[02:56:02] [Dynmap Render Thread/WARN]: 	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
[02:56:02] [Dynmap Render Thread/WARN]: 	... 21 more

• I have looked at all other issues and this is not a duplicate
• I have been able to replicate this

[JurgenKuyper]

We can only test and support the main spigot or paper or forge or fabric version, can you try if this is still apparent on those?

[mibby]

This occurs under Paper dev 113 as well.

[masmc05]

very strange, async catcher should be disabled when stopping the server, did you use a flag similar to "paper.strict-thread-checks"? Because i can't replicate this issue no matter what
Can you try this version https://drive.google.com/file/d/1HQRbX8tXarBpbDvgpPBMlUT5B3Ilockm/view?usp=sharing , i tried to fix this but since i can't replicate, i can't check if it's fixed

[masmc05]

i'll open a pr with changes if it'll fix this

[mibby]

did you use a flag similar to "paper.strict-thread-checks"?

I don't, no.

Can you try this version

Bit weary trying random jar downloads linked, sorry. I would be more willing to test if you forked and committed the changes to a branch or PR though.

[masmc05]

Bit weary trying random jar downloads linked, sorry. I would be more willing to test if you forked and committed the changes to a branch or PR though.

ok, no problem, you can compile yourself from #3820

[mibby]

Unfortunately with that PR commit compiled (and the provided test build), the issue still occurs.

https://paste.gg/p/anonymous/97f8ad79119848b2a83a5096973f301b/files/145a50cc14924b82a392d2261bb3b01a/raw

[20:00:01] [Dynmap Render Thread/ERROR]: Thread Dynmap Render Thread failed main thread check: preparation of chunk data for async save
java.lang.Throwable: null
	at org.spigotmc.AsyncCatcher.catchOp(AsyncCatcher.java:15)
	at net.minecraft.world.level.chunk.storage.ChunkSerializer.getAsyncSaveData(ChunkSerializer.java:465) ~[?:?]
	at jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:577) ~[?:?]
	at org.dynmap.bukkit.helper.v119.AsyncChunkProvider119.lambda$getLoadedChunk$6(AsyncChunkProvider119.java:96) ~[Dynmap-3.4-spigot.jar:?]
	at java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1768) ~[?:?]
	at net.minecraft.util.thread.BlockableEventLoop.execute(BlockableEventLoop.java:100) ~[?:?]
	at java.util.concurrent.CompletableFuture.asyncSupplyStage(CompletableFuture.java:1782) ~[?:?]
	at java.util.concurrent.CompletableFuture.supplyAsync(CompletableFuture.java:2005) ~[?:?]
	at org.dynmap.bukkit.helper.v119.AsyncChunkProvider119.getLoadedChunk(AsyncChunkProvider119.java:94) ~[Dynmap-3.4-spigot.jar:?]
	at org.dynmap.bukkit.helper.v119.MapChunkCache119.getLoadedChunkAsync(MapChunkCache119.java:40) ~[Dynmap-3.4-spigot.jar:?]
	at org.dynmap.common.chunk.GenericMapChunkCache.getLoadedChunksAsync(GenericMapChunkCache.java:803) ~[Dynmap-3.4-spigot.jar:?]
	at org.dynmap.common.chunk.GenericMapChunkCache.loadChunksAsync(GenericMapChunkCache.java:844) ~[Dynmap-3.4-spigot.jar:?]
	at org.dynmap.bukkit.DynmapPlugin$BukkitServer.createMapChunkCache(DynmapPlugin.java:570) ~[Dynmap-3.4-spigot.jar:?]
	at org.dynmap.MapManager$FullWorldRenderState.processTile(MapManager.java:767) ~[Dynmap-3.4-spigot.jar:?]
	at org.dynmap.MapManager$FullWorldRenderState.run(MapManager.java:726) ~[Dynmap-3.4-spigot.jar:?]
	at org.dynmap.MapManager$DynmapScheduledThreadPoolExecutor$1.run(MapManager.java:234) ~[Dynmap-3.4-spigot.jar:?]
	at org.dynmap.MapManager$DynmapScheduledThreadPoolExecutor$2.run(MapManager.java:252) ~[Dynmap-3.4-spigot.jar:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) ~[?:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) ~[?:?]
	at java.lang.Thread.run(Thread.java:833) ~[?:?]

[20:00:07] [Dynmap Render Thread/ERROR]: [dynmap] Exception during render job: world=world, map=null
[20:00:07] [Dynmap Render Thread/WARN]: java.lang.RuntimeException: java.lang.InterruptedException
[20:00:07] [Dynmap Render Thread/WARN]: 	at Dynmap-3.4-spigot.jar//org.dynmap.bukkit.helper.v119.AsyncChunkProvider119.lambda$getLoadedChunk$7(AsyncChunkProvider119.java:117)
[20:00:07] [Dynmap Render Thread/WARN]: 	at Dynmap-3.4-spigot.jar//org.dynmap.bukkit.helper.v119.MapChunkCache119.lambda$getLoadedChunkAsync$0(MapChunkCache119.java:42)
[20:00:07] [Dynmap Render Thread/WARN]: 	at Dynmap-3.4-spigot.jar//org.dynmap.common.chunk.GenericMapChunkCache.lambda$getLoadedChunksAsync$1(GenericMapChunkCache.java:829)
[20:00:07] [Dynmap Render Thread/WARN]: 	at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
[20:00:07] [Dynmap Render Thread/WARN]: 	at Dynmap-3.4-spigot.jar//org.dynmap.common.chunk.GenericMapChunkCache.getLoadedChunksAsync(GenericMapChunkCache.java:827)
[20:00:07] [Dynmap Render Thread/WARN]: 	at Dynmap-3.4-spigot.jar//org.dynmap.common.chunk.GenericMapChunkCache.loadChunksAsync(GenericMapChunkCache.java:844)
[20:00:07] [Dynmap Render Thread/WARN]: 	at Dynmap-3.4-spigot.jar//org.dynmap.bukkit.DynmapPlugin$BukkitServer.createMapChunkCache(DynmapPlugin.java:570)
[20:00:07] [Dynmap Render Thread/WARN]: 	at Dynmap-3.4-spigot.jar//org.dynmap.MapManager$FullWorldRenderState.processTile(MapManager.java:767)
[20:00:07] [Dynmap Render Thread/WARN]: 	at Dynmap-3.4-spigot.jar//org.dynmap.MapManager$FullWorldRenderState.run(MapManager.java:726)
[20:00:07] [Dynmap Render Thread/WARN]: 	at Dynmap-3.4-spigot.jar//org.dynmap.MapManager$DynmapScheduledThreadPoolExecutor$1.run(MapManager.java:234)
[20:00:07] [Dynmap Render Thread/WARN]: 	at Dynmap-3.4-spigot.jar//org.dynmap.MapManager$DynmapScheduledThreadPoolExecutor$2.run(MapManager.java:252)
[20:00:07] [Dynmap Render Thread/WARN]: 	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
[20:00:07] [Dynmap Render Thread/WARN]: 	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
[20:00:07] [Dynmap Render Thread/WARN]: 	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
[20:00:07] [Dynmap Render Thread/WARN]: 	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
[20:00:07] [Dynmap Render Thread/WARN]: 	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
[20:00:07] [Dynmap Render Thread/WARN]: 	at java.base/java.lang.Thread.run(Thread.java:833)
[20:00:07] [Dynmap Render Thread/WARN]: Caused by: java.lang.InterruptedException
[20:00:07] [Dynmap Render Thread/WARN]: 	at java.base/java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:386)
[20:00:07] [Dynmap Render Thread/WARN]: 	at java.base/java.util.concurrent.CompletableFuture.get(CompletableFuture.java:2073)
[20:00:07] [Dynmap Render Thread/WARN]: 	at Dynmap-3.4-spigot.jar//org.dynmap.bukkit.helper.v119.AsyncChunkProvider119.lambda$getLoadedChunk$7(AsyncChunkProvider119.java:115)
[20:00:07] [Dynmap Render Thread/WARN]: 	... 16 more

[masmc05]

Unfortunately with that PR commit compiled (and the provided test build), the issue still occurs.

it doesn't occur, just the async catcher prints the error itself, even if dynmap now handles it well (you can see that this time no stacktrace from dynmap, there were 2 of them, now it's 1), i'll make a change so the check will occur before async catcher could notice

[masmc05]

Can you try to checkout to latest commit in the pr and buid it again and test? (since you built it one time, it should build faster this time)

[mibby]

Can you try to checkout to latest commit in the pr and buid it again and test?

So far so good and no errors when doing a radiusrender and restarting while online. I'll keep monitoring the server log during automated restarts, but assuming fixed with that PR.

[molor]

I also have similar issue during shutdown, but on Paper-387 (1.18.2) and dynmap 3.4-beta-5-806
https://pastebin.com/raw/uinX5pCw
Hope this helps

[masmc05]

I also have similar issue during shutdown, but on Paper-387 (1.18.2) and dynmap 3.4-beta-5-806 https://pastebin.com/raw/uinX5pCw Hope this helps

yeah, seems like what was fixed with the pr, soon it will be merged and in next beta (or version) release this fix will be public