PaperMC/patches/server/1023-Improved-Watchdog-Support.patch

From 0000000000000000000000000000000000000000 Mon Sep 17 00:00:00 2001
From: Aikar <aikar@aikar.co>
Date: Sun, 12 Apr 2020 15:50:48 -0400
Subject: [PATCH] Improved Watchdog Support

Forced Watchdog Crash support and Improve Async Shutdown

If the request to shut down the server is received while we are in
a watchdog hang, immediately treat it as a crash and begin the shutdown
process. Shutdown process is now improved to also shutdown cleanly when
not using restart scripts either.

If a server is deadlocked, a server owner can send SIGUP (or any other signal
the JVM understands to shut down as it currently does) and the watchdog
will no longer need to wait until the full timeout, allowing you to trigger
a close process and try to shut the server down gracefully, saving player and
world data.

Previously there was no way to trigger this outside of waiting for a full watchdog
timeout, which may be set to a really long time...

Additionally, fix everything to do with shutting the server down asynchronously.

Previously, nearly everything about the process was fragile and unsafe. Main might
not have actually been frozen, and might still be manipulating state.

Or, some reuest might ask main to do something in the shutdown but main is dead.

Or worse, other things might start closing down items such as the Console or Thread Pool
before we are fully shutdown.

This change tries to resolve all of these issues by moving everything into the stop
method and guaranteeing only one thread is stopping the server.

We then issue Thread Death to the main thread of another thread initiates the stop process.
We have to ensure Thread Death propagates correctly though to stop main completely.

This is to ensure that if main isn't truely stuck, it's not manipulating state we are trying to save.

This also moves all plugins who register "delayed init" tasks to occur just before "Done" so they
are properly accounted for and wont trip watchdog on init.

diff --git a/src/main/java/com/destroystokyo/paper/Metrics.java b/src/main/java/com/destroystokyo/paper/Metrics.java
index 6aaed8e8bf8c721fc834da5c76ac72a4c3e92458..4b002e8b75d117b726b0de274a76d3596fce015b 100644
--- a/src/main/java/com/destroystokyo/paper/Metrics.java
+++ b/src/main/java/com/destroystokyo/paper/Metrics.java
@@ -92,7 +92,12 @@ public class Metrics {
      * Starts the Scheduler which submits our data every 30 minutes.
      */
     private void startSubmitting() {
-        final Runnable submitTask = this::submitData;
+        final Runnable submitTask = () -> {
+            if (MinecraftServer.getServer().hasStopped()) {
+                return;
+            }
+            submitData();
+        };
 
         // Many servers tend to restart at a fixed time at xx:00 which causes an uneven distribution of requests on the
         // bStats backend. To circumvent this problem, we introduce some randomness into the initial and second delay.
diff --git a/src/main/java/net/minecraft/CrashReport.java b/src/main/java/net/minecraft/CrashReport.java
index 589a8bf75be6ccc59f1e5dd5d8d9afed41c4772d..b24265573fdef5d9a964bcd76146f34542c420cf 100644
--- a/src/main/java/net/minecraft/CrashReport.java
+++ b/src/main/java/net/minecraft/CrashReport.java
@@ -237,6 +237,7 @@ public class CrashReport {
     }
 
     public static CrashReport forThrowable(Throwable cause, String title) {
+        if (cause instanceof ThreadDeath) com.destroystokyo.paper.util.SneakyThrow.sneaky(cause); // Paper
         while (cause instanceof CompletionException && cause.getCause() != null) {
             cause = cause.getCause();
         }
diff --git a/src/main/java/net/minecraft/server/MinecraftServer.java b/src/main/java/net/minecraft/server/MinecraftServer.java
index 64d0e04b6f9c52d90d0bc185b16a8a4768af4ac1..68f60e77e0bfd42b6419491c1d59b6432974216b 100644
--- a/src/main/java/net/minecraft/server/MinecraftServer.java
+++ b/src/main/java/net/minecraft/server/MinecraftServer.java
@@ -307,7 +307,7 @@ public abstract class MinecraftServer extends ReentrantBlockableEventLoop<TickTa
     public java.util.Queue<Runnable> processQueue = new java.util.concurrent.ConcurrentLinkedQueue<Runnable>();
     public int autosavePeriod;
     // Paper - don't store the vanilla dispatcher
-    private boolean forceTicks;
+    public boolean forceTicks; // Paper - Improved watchdog support
     // CraftBukkit end
     // Spigot start
     public static final int TPS = 20;
@@ -320,6 +320,9 @@ public abstract class MinecraftServer extends ReentrantBlockableEventLoop<TickTa
     public static long currentTickLong = 0L; // Paper - track current tick as a long
     public boolean isIteratingOverLevels = false; // Paper - Throw exception on world create while being ticked
 
+    public volatile Thread shutdownThread; // Paper
+    public volatile boolean abnormalExit = false; // Paper
+
     public static <S extends MinecraftServer> S spin(Function<Thread, S> serverFactory) {
         AtomicReference<S> atomicreference = new AtomicReference();
         Thread thread = new io.papermc.paper.util.TickThread(() -> { // Paper - rewrite chunk system
@@ -943,6 +946,7 @@ public abstract class MinecraftServer extends ReentrantBlockableEventLoop<TickTa
     // CraftBukkit start
     private boolean hasStopped = false;
     private boolean hasLoggedStop = false; // Paper - Debugging
+    public volatile boolean hasFullyShutdown = false; // Paper
     private final Object stopLock = new Object();
     public final boolean hasStopped() {
         synchronized (this.stopLock) {
@@ -958,6 +962,19 @@ public abstract class MinecraftServer extends ReentrantBlockableEventLoop<TickTa
             this.hasStopped = true;
         }
         if (!hasLoggedStop && isDebugging()) io.papermc.paper.util.TraceUtil.dumpTraceForThread("Server stopped"); // Paper - Debugging
+        // Paper start - kill main thread, and kill it hard
+        shutdownThread = Thread.currentThread();
+        org.spigotmc.WatchdogThread.doStop(); // Paper
+        if (!isSameThread()) {
+            MinecraftServer.LOGGER.info("Stopping main thread (Ignore any thread death message you see! - DO NOT REPORT THREAD DEATH TO PAPER)");
+            while (this.getRunningThread().isAlive()) {
+                this.getRunningThread().stop();
+                try {
+                    Thread.sleep(1);
+                } catch (InterruptedException e) {}
+            }
+        }
+        // Paper end
         // CraftBukkit end
         if (this.metricsRecorder.isRecording()) {
             this.cancelRecordingMetrics();
@@ -1031,7 +1048,17 @@ public abstract class MinecraftServer extends ReentrantBlockableEventLoop<TickTa
         }
         // Spigot end
 
+        // Paper end - Improved watchdog support; move final shutdown items here
         ca.spottedleaf.moonrise.patches.chunk_system.io.RegionFileIOThread.deinit(); // Paper - rewrite chunk system
+        // Paper start - move final shutdown items here
+        Util.shutdownExecutors();
+        try {
+            net.minecrell.terminalconsole.TerminalConsoleAppender.close(); // Paper - Use TerminalConsoleAppender
+        } catch (final Exception ignored) {
+        }
+        io.papermc.paper.log.CustomLogManager.forceReset(); // Paper - Reset loggers after shutdown
+        this.onServerExit();
+        // Paper end - Improved watchdog support
     }
 
     public String getLocalIp() {
@@ -1126,6 +1153,7 @@ public abstract class MinecraftServer extends ReentrantBlockableEventLoop<TickTa
 
     protected void runServer() {
         try {
+            long serverStartTime = Util.getNanos(); // Paper
             if (!this.initServer()) {
                 throw new IllegalStateException("Failed to initialize server");
             }
@@ -1135,6 +1163,18 @@ public abstract class MinecraftServer extends ReentrantBlockableEventLoop<TickTa
             this.status = this.buildServerStatus();
 
             // Spigot start
+            // Paper start - move done tracking
+            LOGGER.info("Running delayed init tasks");
+            this.server.getScheduler().mainThreadHeartbeat(this.tickCount); // run all 1 tick delay tasks during init,
+            // this is going to be the first thing the tick process does anyways, so move done and run it after
+            // everything is init before watchdog tick.
+            // anything at 3+ won't be caught here but also will trip watchdog....
+            // tasks are default scheduled at -1 + delay, and first tick will tick at 1
+            String doneTime = String.format(java.util.Locale.ROOT, "%.3fs", (double) (Util.getNanos() - serverStartTime) / 1.0E9D);
+            LOGGER.info("Done ({})! For help, type \"help\"", doneTime);
+            // Paper end
+
+            org.spigotmc.WatchdogThread.tick(); // Paper
             org.spigotmc.WatchdogThread.hasStarted = true; // Paper
             Arrays.fill( this.recentTps, 20 );
             // Paper start - further improve server tick loop
@@ -1230,6 +1270,12 @@ public abstract class MinecraftServer extends ReentrantBlockableEventLoop<TickTa
                 JvmProfiler.INSTANCE.onServerTick(this.smoothedTickTimeMillis);
             }
         } catch (Throwable throwable) {
+            // Paper start
+            if (throwable instanceof ThreadDeath) {
+                MinecraftServer.LOGGER.error("Main thread terminated by WatchDog due to hard crash", throwable);
+                return;
+            }
+            // Paper end
             MinecraftServer.LOGGER.error("Encountered an unexpected exception", throwable);
             CrashReport crashreport = MinecraftServer.constructOrExtractCrashReport(throwable);
 
@@ -1254,15 +1300,15 @@ public abstract class MinecraftServer extends ReentrantBlockableEventLoop<TickTa
                     this.services.profileCache().clearExecutor();
                 }
 
-                org.spigotmc.WatchdogThread.doStop(); // Spigot
+                //org.spigotmc.WatchdogThread.doStop(); // Spigot // Paper - move into stop
                 // CraftBukkit start - Restore terminal to original settings
                 try {
-                    net.minecrell.terminalconsole.TerminalConsoleAppender.close(); // Paper - Use TerminalConsoleAppender
+                    //net.minecrell.terminalconsole.TerminalConsoleAppender.close(); // Paper - Move into stop
                 } catch (Exception ignored) {
                 }
                 // CraftBukkit end
-                io.papermc.paper.log.CustomLogManager.forceReset(); // Paper - Reset loggers after shutdown
-                this.onServerExit();
+                //io.papermc.paper.log.CustomLogManager.forceReset(); // Paper - Reset loggers after shutdown
+                //this.onServerExit(); // Paper - moved into stop
             }
 
         }
@@ -1385,6 +1431,12 @@ public abstract class MinecraftServer extends ReentrantBlockableEventLoop<TickTa
 
     @Override
     public TickTask wrapRunnable(Runnable runnable) {
+        // Paper start - anything that does try to post to main during watchdog crash, run on watchdog
+        if (this.hasStopped && Thread.currentThread().equals(shutdownThread)) {
+            runnable.run();
+            runnable = () -> {};
+        }
+        // Paper end
         return new TickTask(this.tickCount, runnable);
     }
 
@@ -2204,7 +2256,15 @@ public abstract class MinecraftServer extends ReentrantBlockableEventLoop<TickTa
             this.worldData.setDataConfiguration(worlddataconfiguration);
             this.resources.managers.updateRegistryTags();
             this.potionBrewing = this.potionBrewing.reload(this.worldData.enabledFeatures()); // Paper - Custom Potion Mixes
-            this.getPlayerList().saveAll();
+            // Paper start
+            if (Thread.currentThread() != this.serverThread) {
+                return;
+            }
+            // this.getPlayerList().saveAll(); // Paper - we don't need to save everything, just advancements // TODO Move this to a different patch
+            for (ServerPlayer player : this.getPlayerList().getPlayers()) {
+                player.getAdvancements().save();
+            }
+            // Paper end
             this.getPlayerList().reloadResources();
             this.functionManager.replaceLibrary(this.resources.managers.getFunctionLibrary());
             this.structureTemplateManager.onResourceManagerReload(this.resources.resourceManager);
diff --git a/src/main/java/net/minecraft/server/dedicated/DedicatedServer.java b/src/main/java/net/minecraft/server/dedicated/DedicatedServer.java
index 7d2896918ff5fed37e5de5a22c37b0c7f32634a8..7d82cc6b847124cf4225428ba310309544928148 100644
--- a/src/main/java/net/minecraft/server/dedicated/DedicatedServer.java
+++ b/src/main/java/net/minecraft/server/dedicated/DedicatedServer.java
@@ -328,7 +328,7 @@ public class DedicatedServer extends MinecraftServer implements ServerInterface
             long j = Util.getNanos() - i;
             String s = String.format(Locale.ROOT, "%.3fs", (double) j / 1.0E9D);
 
-            DedicatedServer.LOGGER.info("Done ({})! For help, type \"help\"", s);
+            //DedicatedServer.LOGGER.info("Done ({})! For help, type \"help\"", s); // Paper moved to after init
             if (dedicatedserverproperties.announcePlayerAchievements != null) {
                 ((GameRules.BooleanValue) this.getGameRules().getRule(GameRules.RULE_ANNOUNCE_ADVANCEMENTS)).set(dedicatedserverproperties.announcePlayerAchievements, this.overworld()); // CraftBukkit - per-world
             }
@@ -462,7 +462,8 @@ public class DedicatedServer extends MinecraftServer implements ServerInterface
             // this.remoteStatusListener.stop(); // Paper - don't wait for remote connections
         }
 
-        System.exit(0); // CraftBukkit
+        hasFullyShutdown = true; // Paper
+        System.exit(this.abnormalExit ? 70 : 0); // CraftBukkit // Paper
     }
 
     @Override
@@ -842,7 +843,7 @@ public class DedicatedServer extends MinecraftServer implements ServerInterface
     @Override
     public void stopServer() {
         super.stopServer();
-        Util.shutdownExecutors();
+        //Util.shutdownExecutors(); // Paper - moved into super
         SkullBlockEntity.clear();
     }
 
diff --git a/src/main/java/net/minecraft/server/players/PlayerList.java b/src/main/java/net/minecraft/server/players/PlayerList.java
index 3d30427e75bdfb9cf453fb5cd2a344227da1641a..ef177f21d654d69c128f3f39ea58f2d8ee598628 100644
--- a/src/main/java/net/minecraft/server/players/PlayerList.java
+++ b/src/main/java/net/minecraft/server/players/PlayerList.java
@@ -604,7 +604,7 @@ public abstract class PlayerList {
         this.cserver.getPluginManager().callEvent(playerQuitEvent);
         entityplayer.getBukkitEntity().disconnect(playerQuitEvent.getQuitMessage());
 
-        entityplayer.doTick(); // SPIGOT-924
+        if (server.isSameThread()) entityplayer.doTick(); // SPIGOT-924 // Paper - don't tick during emergency shutdowns (Watchdog)
         // CraftBukkit end
 
         // Paper start - Configurable player collision; Remove from collideRule team if needed
diff --git a/src/main/java/net/minecraft/util/thread/BlockableEventLoop.java b/src/main/java/net/minecraft/util/thread/BlockableEventLoop.java
index 2510589400b3012b827efcab477c6483d9d55901..43487a9ee202c5b0e5a416519939111f77b3059c 100644
--- a/src/main/java/net/minecraft/util/thread/BlockableEventLoop.java
+++ b/src/main/java/net/minecraft/util/thread/BlockableEventLoop.java
@@ -150,6 +150,7 @@ public abstract class BlockableEventLoop<R extends Runnable> implements Profiler
         try {
             task.run();
         } catch (Exception var3) {
+            if (var3.getCause() instanceof ThreadDeath) throw var3; // Paper
             LOGGER.error(LogUtils.FATAL_MARKER, "Error executing task on {}", this.name(), var3);
         }
     }
diff --git a/src/main/java/net/minecraft/world/level/Level.java b/src/main/java/net/minecraft/world/level/Level.java
index 55e841269585feb6a083b48ffeecea30cc65f6d6..fee155c81df385faa474e3aec777a30375ecb07d 100644
--- a/src/main/java/net/minecraft/world/level/Level.java
+++ b/src/main/java/net/minecraft/world/level/Level.java
@@ -982,6 +982,7 @@ public abstract class Level implements LevelAccessor, AutoCloseable, ca.spottedl
         try {
             tickConsumer.accept(entity);
         } catch (Throwable throwable) {
+            if (throwable instanceof ThreadDeath) throw throwable; // Paper
             // Paper start - Prevent block entity and entity crashes
             final String msg = String.format("Entity threw exception at %s:%s,%s,%s", entity.level().getWorld().getName(), entity.getX(), entity.getY(), entity.getZ());
             MinecraftServer.LOGGER.error(msg, throwable);
diff --git a/src/main/java/net/minecraft/world/level/chunk/LevelChunk.java b/src/main/java/net/minecraft/world/level/chunk/LevelChunk.java
index b2a06fc1192cd6050d6d7ea8620a4fa5a12182cc..d388fbcbff63928f0e9140c02400a63ba8f19d9c 100644
--- a/src/main/java/net/minecraft/world/level/chunk/LevelChunk.java
+++ b/src/main/java/net/minecraft/world/level/chunk/LevelChunk.java
@@ -1006,6 +1006,7 @@ public class LevelChunk extends ChunkAccess implements ca.spottedleaf.moonrise.p
 
                         gameprofilerfiller.pop();
                     } catch (Throwable throwable) {
+                        if (throwable instanceof ThreadDeath) throw throwable; // Paper
                         // Paper start - Prevent block entity and entity crashes
                         final String msg = String.format("BlockEntity threw exception at %s:%s,%s,%s", LevelChunk.this.getLevel().getWorld().getName(), this.getPos().getX(), this.getPos().getY(), this.getPos().getZ());
                         net.minecraft.server.MinecraftServer.LOGGER.error(msg, throwable);
diff --git a/src/main/java/org/bukkit/craftbukkit/util/ServerShutdownThread.java b/src/main/java/org/bukkit/craftbukkit/util/ServerShutdownThread.java
index c6e8441e299f477ddb22c1ce2618710763978f1a..e8e93538dfd71de86515d9405f728db1631e949a 100644
--- a/src/main/java/org/bukkit/craftbukkit/util/ServerShutdownThread.java
+++ b/src/main/java/org/bukkit/craftbukkit/util/ServerShutdownThread.java
@@ -12,11 +12,27 @@ public class ServerShutdownThread extends Thread {
     @Override
     public void run() {
         try {
+            // Paper start - try to shutdown on main
+            server.safeShutdown(false, false);
+            for (int i = 1000; i > 0 && !server.hasStopped(); i -= 100) {
+                Thread.sleep(100);
+            }
+            if (server.hasStopped()) {
+                while (!server.hasFullyShutdown) Thread.sleep(1000);
+                return;
+            }
+            // Looks stalled, close async
             org.spigotmc.AsyncCatcher.enabled = false; // Spigot
+            server.forceTicks = true;
             this.server.close();
+            while (!server.hasFullyShutdown) Thread.sleep(1000);
+        } catch (InterruptedException e) {
+            e.printStackTrace();
+            // Paper end
         } finally {
+            org.apache.logging.log4j.LogManager.shutdown(); // Paper
             try {
-                net.minecrell.terminalconsole.TerminalConsoleAppender.close(); // Paper - Use TerminalConsoleAppender
+                //net.minecrell.terminalconsole.TerminalConsoleAppender.close(); // Paper - Move into stop
             } catch (Exception e) {
             }
         }
diff --git a/src/main/java/org/spigotmc/RestartCommand.java b/src/main/java/org/spigotmc/RestartCommand.java
index f3fa0340babfc5eb627066115164e2d885c602c2..9ce945dce3ac8aa1d4eb55c41115f989b985d46d 100644
--- a/src/main/java/org/spigotmc/RestartCommand.java
+++ b/src/main/java/org/spigotmc/RestartCommand.java
@@ -139,7 +139,7 @@ public class RestartCommand extends Command
     // Paper end
 
     // Paper start - copied from above and modified to return if the hook registered
-    private static boolean addShutdownHook(String restartScript)
+    public static boolean addShutdownHook(String restartScript) // Paper
     {
         String[] split = restartScript.split( " " );
         if ( split.length > 0 && new File( split[0] ).isFile() )
diff --git a/src/main/java/org/spigotmc/WatchdogThread.java b/src/main/java/org/spigotmc/WatchdogThread.java
index 7507e3058e7519a3e13b3be061746151a71b8f20..e5e41dc2d4f7a8c3fea704212507ca0b951664db 100644
--- a/src/main/java/org/spigotmc/WatchdogThread.java
+++ b/src/main/java/org/spigotmc/WatchdogThread.java
@@ -11,6 +11,7 @@ import org.bukkit.Bukkit;
 public class WatchdogThread extends Thread
 {
 
+    public static final boolean DISABLE_WATCHDOG = Boolean.getBoolean("disable.watchdog"); // Paper - Improved watchdog support
     private static WatchdogThread instance;
     private long timeoutTime;
     private boolean restart;
@@ -39,6 +40,7 @@ public class WatchdogThread extends Thread
     {
         if ( WatchdogThread.instance == null )
         {
+            if (timeoutTime <= 0) timeoutTime = 300; // Paper
             WatchdogThread.instance = new WatchdogThread( timeoutTime * 1000L, restart );
             WatchdogThread.instance.start();
         } else
@@ -70,12 +72,13 @@ public class WatchdogThread extends Thread
             // Paper start
             Logger log = Bukkit.getServer().getLogger();
             long currentTime = WatchdogThread.monotonicMillis();
-            if ( this.lastTick != 0 && this.timeoutTime > 0 && currentTime > this.lastTick + this.earlyWarningEvery && !Boolean.getBoolean("disable.watchdog")) // Paper - Add property to disable
+            MinecraftServer server = MinecraftServer.getServer();
+            if ( this.lastTick != 0 && this.timeoutTime > 0 && WatchdogThread.hasStarted && (!server.isRunning() || (currentTime > this.lastTick + this.earlyWarningEvery && !DISABLE_WATCHDOG) )) // Paper - add property to disable
             {
-                boolean isLongTimeout = currentTime > lastTick + timeoutTime;
+                boolean isLongTimeout = currentTime > lastTick + timeoutTime || (!server.isRunning() && !server.hasStopped() && currentTime > lastTick + 1000);
                 // Don't spam early warning dumps
                 if ( !isLongTimeout && (earlyWarningEvery <= 0 || !hasStarted || currentTime < lastEarlyWarning + earlyWarningEvery || currentTime < lastTick + earlyWarningDelay)) continue;
-                if ( !isLongTimeout && MinecraftServer.getServer().hasStopped()) continue; // Don't spam early watchdog warnings during shutdown, we'll come back to this...
+                if ( !isLongTimeout && server.hasStopped()) continue; // Don't spam early watchdog warnings during shutdown, we'll come back to this...
                 lastEarlyWarning = currentTime;
                 if (isLongTimeout) {
                 // Paper end
@@ -136,9 +139,24 @@ public class WatchdogThread extends Thread
 
                 if ( isLongTimeout )
                 {
-                if ( this.restart && !MinecraftServer.getServer().hasStopped() )
+                if ( !server.hasStopped() )
                 {
-                    RestartCommand.restart();
+                    AsyncCatcher.enabled = false; // Disable async catcher incase it interferes with us
+                    server.forceTicks = true;
+                    if (restart) {
+                        RestartCommand.addShutdownHook( SpigotConfig.restartScript );
+                    }
+                    // try one last chance to safe shutdown on main incase it 'comes back'
+                    server.abnormalExit = true;
+                    server.safeShutdown(false, restart);
+                    try {
+                        Thread.sleep(1000);
+                    } catch (InterruptedException e) {
+                        e.printStackTrace();
+                    }
+                    if (!server.hasStopped()) {
+                        server.close();
+                    }
                 }
                 break;
                 } // Paper end
diff --git a/src/main/resources/log4j2.xml b/src/main/resources/log4j2.xml
index 637d64da9938e51a97338b9253b43889585c67bb..d2a75850af9c6ad2aca66a5f994f1b587d73eac4 100644
--- a/src/main/resources/log4j2.xml
+++ b/src/main/resources/log4j2.xml
@@ -1,5 +1,5 @@
 <?xml version="1.0" encoding="UTF-8"?>
-<Configuration status="WARN">
+<Configuration status="WARN" shutdownHook="disable">
     <Appenders>
         <Queue name="ServerGuiConsole">
             <PatternLayout pattern="[%d{HH:mm:ss} %level]: %msg{nolookups}%n" />