dynmap icon indicating copy to clipboard operation
dynmap copied to clipboard

Published 20 hours ago • verified publisher icon webbukkit

IllegalStateException: Asynchronous preparation of chunk data for async save!

Open mibby opened this issue 1 year ago • 9 comments

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
  • [x] I have looked at all other issues and this is not a duplicate
  • [x] I have been able to replicate this

mibby avatar Aug 07 '22 10:08 mibby

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?

JurgenKuyper avatar Aug 07 '22 10:08 JurgenKuyper

This occurs under Paper dev 113 as well.

mibby avatar Aug 07 '22 10:08 mibby

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 avatar Aug 07 '22 12:08 masmc05

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

masmc05 avatar Aug 07 '22 12:08 masmc05

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.

mibby avatar Aug 07 '22 19:08 mibby

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 https://github.com/webbukkit/dynmap/pull/3820

masmc05 avatar Aug 08 '22 08:08 masmc05

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

mibby avatar Aug 11 '22 04:08 mibby

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 avatar Aug 11 '22 08:08 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)

masmc05 avatar Aug 11 '22 08:08 masmc05

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.

mibby avatar Aug 13 '22 01:08 mibby

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

molor avatar Aug 13 '22 08:08 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

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

masmc05 avatar Aug 13 '22 09:08 masmc05