search

Szum123321 / textile_backup

Backup Mod for Fabric
https://www.curseforge.com/minecraft/mc-mods/textile-backup
GNU General Public License v3.0
90 stars 29 forks source link

`server.saveAll` is called on non-server-main thread, which is not thread-safe #136

Closed qouteall closed 12 months ago

qouteall commented 1 year ago

In

https://github.com/Szum123321/textile_backup/blob/2.x/src/main/java/net/szum123321/textile_backup/core/create/ExecutableBackup.java#L69

server.saveAll may get called in a thread that's not the server main thread, which is not thread safe.

I found this issue when debugging compatibility issue with Immersive Portals https://github.com/iPortalTeam/ImmersivePortalsMod/issues/1402

When using /backup start command when ImmPtl is installed, this assertion will fail https://github.com/iPortalTeam/ImmersivePortalsMod/blob/v3.2.1-mc1.20.1/imm_ptl_core/src/main/java/qouteall/imm_ptl/core/chunk_loading/ImmPtlChunkTickets.java#L167 (Textile backup does not log the exception. This caused some difficulty in debugging.)

WallyCZ commented 1 year ago

I guess this excpetion i got is because of this. It crashed the whole server...

[17:32:07] [Server thread/INFO]: [Textile Backup] Warning! Server backup will begin shortly. You may experience some lag.
[17:32:07] [Server thread/INFO]: [Textile Backup] Backup started by: Timer on: 2023.08.27_17-32-07
[17:32:07] [pool-7-thread-1/INFO]: [Textile Backup] Saving server...
[17:32:08] [Server thread/ERROR]: Encountered an unexpected exception
net.minecraft.class_148: Exception ticking world
    at net.minecraft.server.MinecraftServer.method_3813(MinecraftServer.java:901) ~[server-intermediary.jar:?]
    at net.minecraft.class_3176.method_3813(class_3176.java:283) ~[server-intermediary.jar:?]
    at net.minecraft.server.MinecraftServer.method_3748(MinecraftServer.java:824) ~[server-intermediary.jar:?]
    at net.minecraft.server.MinecraftServer.method_29741(MinecraftServer.java:671) ~[server-intermediary.jar:?]
    at net.minecraft.server.MinecraftServer.method_29739(MinecraftServer.java:265) ~[server-intermediary.jar:?]
    at java.lang.Thread.run(Unknown Source) ~[?:?]
Caused by: java.lang.NullPointerException: Cannot invoke "it.unimi.dsi.fastutil.longs.LongArrayList.getLong(int)" because "this.wrapped" is null
    at it.unimi.dsi.fastutil.longs.LongOpenHashSet$SetIterator.nextLong(LongOpenHashSet.java:545) ~[fastutil-8.5.9.jar:?]
    at net.minecraft.class_3204$class_3948.method_14057(class_3204.java:443) ~[server-intermediary.jar:?]
    at net.minecraft.class_3204.method_15892(class_3204.java:119) ~[server-intermediary.jar:?]
    at net.minecraft.class_3215.method_16155(class_3215.java:286) ~[server-intermediary.jar:?]
    at net.minecraft.class_3215.method_12127(class_3215.java:323) ~[server-intermediary.jar:?]
    at net.minecraft.class_3218.method_18765(class_3218.java:333) ~[server-intermediary.jar:?]
    at net.minecraft.server.MinecraftServer.method_3813(MinecraftServer.java:897) ~[server-intermediary.jar:?]
    ... 5 more
[17:32:08] [Server thread/ERROR]: This crash report has been saved to: /data/./crash-reports/crash-2023-08-27_17.32.08-sever.txt
[17:32:08] [pool-7-thread-1/INFO]: ThreadedAnvilChunkStorage (world): All chunks are saved
[17:32:08] [pool-7-thread-1/INFO]: ThreadedAnvilChunkStorage (DIM1): All chunks are saved
[17:32:08] [pool-7-thread-1/INFO]: ThreadedAnvilChunkStorage (DIM-1): All chunks are saved
[17:32:08] [Server thread/INFO]: Stopped modpack hosting
[17:32:08] [pool-7-thread-1/INFO]: ThreadedAnvilChunkStorage: All dimensions are saved
[17:32:08] [pool-7-thread-1/INFO]: [Textile Backup] Starting backup
[17:32:08] [Server thread/INFO]: [Dynmap] Unloaded 11 components.
[17:32:08] [Server thread/INFO]: [Dynmap] Stopping map renderer...
[17:32:09] [Server thread/INFO]: [Dynmap] Saved 383 pending tile renders in world 'world'
[17:32:10] [Server thread/INFO]: [Dynmap] Disabled
[17:32:10] [Server thread/INFO]: Starting shutdown process...
[17:32:10] [Server thread/INFO]: Closing storage...
[17:32:10] [Server thread/INFO]: Goodbye!
[17:32:10] [Server thread/INFO]: Stopping server
[17:32:10] [Server thread/INFO]: Saving players
[17:32:10] [Server thread/INFO]: wally lost connection: Server closed
[17:32:10] [Server thread/INFO]: wally left the game
[17:32:10] [Server thread/INFO]: Saving worlds
[17:32:11] [Server thread/INFO]: Saving chunks for level 'ServerLevel[world]'/minecraft:overworld
[17:32:12] [Server thread/INFO]: Saving chunks for level 'ServerLevel[world]'/minecraft:the_end
[17:32:12] [Server thread/INFO]: Saving chunks for level 'ServerLevel[world]'/minecraft:the_nether
[17:32:12] [Server thread/INFO]: ThreadedAnvilChunkStorage (world): All chunks are saved
[17:32:12] [Server thread/INFO]: ThreadedAnvilChunkStorage (DIM1): All chunks are saved
[17:32:12] [Server thread/INFO]: ThreadedAnvilChunkStorage (DIM-1): All chunks are saved
[17:32:12] [Server thread/INFO]: ThreadedAnvilChunkStorage: All dimensions are saved
[17:32:13] [Server thread/ERROR]: [Textile Backup] Timeout occurred while waiting for currently running backups to finish!
[17:32:13] [pool-7-thread-1/ERROR]: [Textile Backup] An exception occurred when trying to create a new backup file!
java.lang.InterruptedException: null
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(Unknown Source) ~[?:?]
    at java.util.concurrent.CountDownLatch.await(Unknown Source) ~[?:?]
    at net.szum123321.textile_backup.core.digest.FileTreeHashBuilder.getValue(FileTreeHashBuilder.java:61) ~[textile_backup-3.1.0-1.20.jar:?]
    at net.szum123321.textile_backup.core.create.compressors.AbstractCompressor.createArchive(AbstractCompressor.java:91) ~[textile_backup-3.1.0-1.20.jar:?]
    at net.szum123321.textile_backup.core.create.ExecutableBackup.call(ExecutableBackup.java:104) ~[textile_backup-3.1.0-1.20.jar:?]
    at net.szum123321.textile_backup.core.create.ExecutableBackup.call(ExecutableBackup.java:25) ~[textile_backup-3.1.0-1.20.jar:?]
    at java.util.concurrent.FutureTask.run(Unknown Source) ~[?:?]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) ~[?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) ~[?:?]
    at java.lang.Thread.run(Unknown Source) ~[?:?]
[17:32:13] [Server thread/ERROR]: [Textile Backup] Couldn't shut down the executor!
[17:32:13] [Server thread/INFO]: [Textile Backup] Warning! Server backup will begin shortly. You may experience some lag.
[17:32:13] [Server thread/INFO]: [Textile Backup] Backup started by: Server Shutdown on: 2023.08.27_17-32-13
[17:32:13] [Server thread/INFO]: [Textile Backup] Starting backup
failed to ping localhost:25565 : could not connect to Minecraft server: dial tcp 127.0.0.1:25565: connect: connection refused[Autopause loop] All clients disconnected - pausing in 600 seconds
failed to ping localhost:25565 : could not connect to Minecraft server: dial tcp 127.0.0.1:25565: connect: connection refusedfailed to ping localhost:25565 : could not connect to Minecraft server: dial tcp 127.0.0.1:25565: connect: connection refused[17:32:44] [Server thread/INFO]: [Textile Backup] Compression took: 31.931 seconds.
[17:32:45] [Server thread/INFO]: [Textile Backup] Deleted: /data/backup/world/2023.08.23_17-27-14.zip
[17:32:45] [Server thread/INFO]: [Textile Backup] Done!
[17:32:45] [Server thread/INFO]: Thread RCON Listener stopped
failed to ping localhost:25565 : could not connect to Minecraft server: dial tcp 127.0.0.1:25565: connect: connection refusedfailed to ping localhost:25565 : could not connect to Minecraft server: dial tcp 127.0.0.1:25565: connect: connection refusedfailed to ping localhost:25565 : could not connect to Minecraft server: dial tcp 127.0.0.1:25565: connect: connection refusedfailed to ping localhost:25565 : could not connect to Minecraft server: dial tcp 127.0.0.1:25565: connect: connection refusedfailed to ping localhost:25565 : could not connect to Minecraft server: dial tcp 127.0.0.1:25565: connect: connection refusedfailed to ping localhost:25565 : could not connect to Minecraft server: dial tcp 127.0.0.1:25565: connect: connection refused
MichailiK commented 1 year ago

This has caused our SMP server to occassionally crash during scheduled backups. This is a major issue & dealbreaker for us, so I came up with a somewhat hacky workaround after some tinkering: https://github.com/MichailiK/textile_backup/commit/7d60c45904b1bbb223534f5ffa3525a5e926ee24. This ensures that world saving can only happen on the server thread. A build of this workaround is available on my fork's releases.

Szum123321 commented 12 months ago

All related to #123. Closing.