From 0000000000000000000000000000000000000000 Mon Sep 17 00:00:00 2001 From: Aikar 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 e3b74dbdf8e14219a56fab939f3174e0c2f66de6..218f5bafeed8551b55b91c7fccaf6935c8b631ca 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 c54530d1c66845b190a9cb6d06f985943bb4dbe1..35c9b3e6c5a2d11b4dbd491b16647df105960d1a 100644 --- a/src/main/java/net/minecraft/CrashReport.java +++ b/src/main/java/net/minecraft/CrashReport.java @@ -228,6 +228,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 64370c9c5e443f8e84e7f2f018c56f0223eb4b24..cab914abbc6c655895f09d71f253889a0dcc4e02 100644 --- a/src/main/java/net/minecraft/server/MinecraftServer.java +++ b/src/main/java/net/minecraft/server/MinecraftServer.java @@ -297,7 +297,7 @@ public abstract class MinecraftServer extends ReentrantBlockableEventLoop processQueue = new java.util.concurrent.ConcurrentLinkedQueue(); public int autosavePeriod; public Commands vanillaCommandDispatcher; - private boolean forceTicks; + public boolean forceTicks; // Paper // CraftBukkit end // Spigot start public static final int TPS = 20; @@ -308,6 +308,9 @@ public abstract class MinecraftServer extends ReentrantBlockableEventLoop S spin(Function serverFactory) { AtomicReference atomicreference = new AtomicReference(); Thread thread = new Thread(() -> { @@ -914,6 +917,7 @@ public abstract class MinecraftServer extends ReentrantBlockableEventLoop {}; + } + // Paper end return new TickTask(this.tickCount, runnable); } @@ -1461,6 +1514,7 @@ public abstract class MinecraftServer extends ReentrantBlockableEventLoop { CompletableFuture completablefuture; diff --git a/src/main/java/net/minecraft/server/players/PlayerList.java b/src/main/java/net/minecraft/server/players/PlayerList.java index 8901bb31524613bf3fbec3cc5d3c228f8b3f43a4..4e26475bf0f541d6b2f8b6eccfeaeb9ee5b4b2b8 100644 --- a/src/main/java/net/minecraft/server/players/PlayerList.java +++ b/src/main/java/net/minecraft/server/players/PlayerList.java @@ -512,7 +512,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 - 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 58692386e24723a1075ff4f4cc70f40ed957c52f..af5097592835ea46336052fed5bf98760fe18ac8 100644 --- a/src/main/java/net/minecraft/util/thread/BlockableEventLoop.java +++ b/src/main/java/net/minecraft/util/thread/BlockableEventLoop.java @@ -148,6 +148,7 @@ public abstract class BlockableEventLoop implements Profiler try { task.run(); } catch (Exception var3) { + if (var3.getCause() instanceof ThreadDeath) throw var3; // Paper LOGGER.fatal("Error executing task on {}", this.name(), var3); throw var3; } diff --git a/src/main/java/net/minecraft/world/level/Level.java b/src/main/java/net/minecraft/world/level/Level.java index 9842e4d39130f45481b643df38ee4b25076c5c08..4a77494ddb94d5fd2d82665c6bd4e513b66f1d9f 100644 --- a/src/main/java/net/minecraft/world/level/Level.java +++ b/src/main/java/net/minecraft/world/level/Level.java @@ -831,6 +831,7 @@ public abstract class Level implements LevelAccessor, AutoCloseable { try { tickConsumer.accept(entity); } catch (Throwable throwable) { + if (throwable instanceof ThreadDeath) throw throwable; // Paper // Paper start - Prevent tile 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 1df4ddab06b6065464302bdc0e4eb0950964fa84..b92da719a5d35a60a2e13ccb0f55c41b242f9b50 100644 --- a/src/main/java/net/minecraft/world/level/chunk/LevelChunk.java +++ b/src/main/java/net/minecraft/world/level/chunk/LevelChunk.java @@ -1068,6 +1068,7 @@ public class LevelChunk extends ChunkAccess { gameprofilerfiller.pop(); } catch (Throwable throwable) { + if (throwable instanceof ThreadDeath) throw throwable; // Paper // Paper start - Prevent tile 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/CraftServer.java b/src/main/java/org/bukkit/craftbukkit/CraftServer.java index b9b5c7c3d4e991dd62ed7acb33e02c2523fe5d46..c7e2ce7d2fa80c6c97ebe94ec5c36c9eb7356f45 100644 --- a/src/main/java/org/bukkit/craftbukkit/CraftServer.java +++ b/src/main/java/org/bukkit/craftbukkit/CraftServer.java @@ -2049,7 +2049,7 @@ public final class CraftServer implements Server { @Override public boolean isPrimaryThread() { - return Thread.currentThread().equals(console.serverThread); // Paper - Fix issues with detecting main thread properly + return Thread.currentThread().equals(console.serverThread) || Thread.currentThread().equals(net.minecraft.server.MinecraftServer.getServer().shutdownThread); // Paper - Fix issues with detecting main thread properly, the only time Watchdog will be used is during a crash shutdown which is a "try our best" scenario } // Paper start diff --git a/src/main/java/org/bukkit/craftbukkit/Main.java b/src/main/java/org/bukkit/craftbukkit/Main.java index 867c0802557375b63e69907bdb3ccd66644f1418..1ade239c9aacf2334c6dee773e0b37f3969723da 100644 --- a/src/main/java/org/bukkit/craftbukkit/Main.java +++ b/src/main/java/org/bukkit/craftbukkit/Main.java @@ -12,6 +12,8 @@ import java.util.logging.Level; import java.util.logging.Logger; import joptsimple.OptionParser; import joptsimple.OptionSet; +import net.minecraft.util.ExceptionCollector; +import net.minecraft.world.level.lighting.LayerLightEventListener; import net.minecrell.terminalconsole.TerminalConsoleAppender; // Paper public class Main { @@ -162,6 +164,36 @@ public class Main { OptionSet options = null; + // Paper start - preload logger classes to avoid plugins mixing versions + tryPreloadClass("org.apache.logging.log4j.core.Core"); + tryPreloadClass("org.apache.logging.log4j.core.appender.AsyncAppender"); + tryPreloadClass("org.apache.logging.log4j.core.Appender"); + tryPreloadClass("org.apache.logging.log4j.core.ContextDataInjector"); + tryPreloadClass("org.apache.logging.log4j.core.Filter"); + tryPreloadClass("org.apache.logging.log4j.core.ErrorHandler"); + tryPreloadClass("org.apache.logging.log4j.core.LogEvent"); + tryPreloadClass("org.apache.logging.log4j.core.Logger"); + tryPreloadClass("org.apache.logging.log4j.core.LoggerContext"); + tryPreloadClass("org.apache.logging.log4j.core.LogEventListener"); + tryPreloadClass("org.apache.logging.log4j.core.AbstractLogEvent"); + tryPreloadClass("org.apache.logging.log4j.message.AsynchronouslyFormattable"); + tryPreloadClass("org.apache.logging.log4j.message.FormattedMessage"); + tryPreloadClass("org.apache.logging.log4j.message.ParameterizedMessage"); + tryPreloadClass("org.apache.logging.log4j.message.Message"); + tryPreloadClass("org.apache.logging.log4j.message.MessageFactory"); + tryPreloadClass("org.apache.logging.log4j.message.TimestampMessage"); + tryPreloadClass("org.apache.logging.log4j.message.SimpleMessage"); + tryPreloadClass("org.apache.logging.log4j.core.async.AsyncLogger"); + tryPreloadClass("org.apache.logging.log4j.core.async.AsyncLoggerContext"); + tryPreloadClass("org.apache.logging.log4j.core.async.AsyncQueueFullPolicy"); + tryPreloadClass("org.apache.logging.log4j.core.async.AsyncLoggerDisruptor"); + tryPreloadClass("org.apache.logging.log4j.core.async.RingBufferLogEvent"); + tryPreloadClass("org.apache.logging.log4j.core.async.DisruptorUtil"); + tryPreloadClass("org.apache.logging.log4j.core.async.RingBufferLogEventHandler"); + tryPreloadClass("org.apache.logging.log4j.core.impl.ThrowableProxy"); + tryPreloadClass("org.apache.logging.log4j.core.impl.ExtendedClassInfo"); + tryPreloadClass("org.apache.logging.log4j.core.impl.ExtendedStackTraceElement"); + // Paper end try { options = parser.parse(args); } catch (joptsimple.OptionException ex) { @@ -261,8 +293,64 @@ public class Main { } catch (Throwable t) { t.printStackTrace(); } + // Paper start + // load some required classes to avoid errors during shutdown if jar is replaced + // also to guarantee our version loads over plugins + tryPreloadClass("com.destroystokyo.paper.util.SneakyThrow"); + tryPreloadClass("com.google.common.collect.Iterators$PeekingImpl"); + tryPreloadClass("com.google.common.collect.MapMakerInternalMap$Values"); + tryPreloadClass("com.google.common.collect.MapMakerInternalMap$ValueIterator"); + tryPreloadClass("com.google.common.collect.MapMakerInternalMap$WriteThroughEntry"); + tryPreloadClass("com.google.common.collect.Iterables"); + for (int i = 1; i <= 15; i++) { + tryPreloadClass("com.google.common.collect.Iterables$" + i, false); + } + tryPreloadClass("org.apache.commons.lang3.mutable.MutableBoolean"); + tryPreloadClass("org.apache.commons.lang3.mutable.MutableInt"); + tryPreloadClass("org.jline.terminal.impl.MouseSupport"); + tryPreloadClass("org.jline.terminal.impl.MouseSupport$1"); + tryPreloadClass("org.jline.terminal.Terminal$MouseTracking"); + tryPreloadClass("co.aikar.timings.TimingHistory"); + tryPreloadClass("co.aikar.timings.TimingHistory$MinuteReport"); + tryPreloadClass("io.netty.channel.AbstractChannelHandlerContext"); + tryPreloadClass("io.netty.channel.AbstractChannelHandlerContext$11"); + tryPreloadClass("io.netty.channel.AbstractChannelHandlerContext$12"); + tryPreloadClass("io.netty.channel.AbstractChannel$AbstractUnsafe$8"); + tryPreloadClass("io.netty.util.concurrent.DefaultPromise"); + tryPreloadClass("io.netty.util.concurrent.DefaultPromise$1"); + tryPreloadClass("io.netty.util.internal.PromiseNotificationUtil"); + tryPreloadClass("io.netty.util.internal.SystemPropertyUtil"); + tryPreloadClass("org.bukkit.craftbukkit.scheduler.CraftScheduler"); + tryPreloadClass("org.bukkit.craftbukkit.scheduler.CraftScheduler$1"); + tryPreloadClass("org.bukkit.craftbukkit.scheduler.CraftScheduler$2"); + tryPreloadClass("org.bukkit.craftbukkit.scheduler.CraftScheduler$3"); + tryPreloadClass("org.bukkit.craftbukkit.scheduler.CraftScheduler$4"); + tryPreloadClass("org.slf4j.helpers.MessageFormatter"); + tryPreloadClass("org.slf4j.helpers.FormattingTuple"); + tryPreloadClass("org.slf4j.helpers.BasicMarker"); + tryPreloadClass("org.slf4j.helpers.Util"); + tryPreloadClass("com.destroystokyo.paper.event.player.PlayerConnectionCloseEvent"); + tryPreloadClass("com.destroystokyo.paper.event.entity.EntityRemoveFromWorldEvent"); + // Minecraft, seen during saving + tryPreloadClass(LayerLightEventListener.DummyLightLayerEventListener.class.getName()); + tryPreloadClass(LayerLightEventListener.class.getName()); + tryPreloadClass(ExceptionCollector.class.getName()); + // Paper end + } + } + + // Paper start + private static void tryPreloadClass(String className) { + tryPreloadClass(className, true); + } + private static void tryPreloadClass(String className, boolean printError) { + try { + Class.forName(className); + } catch (ClassNotFoundException e) { + if (printError) System.err.println("An expected class " + className + " was not found for preloading: " + e.getMessage()); } } + // Paper end private static List asList(String... params) { return Arrays.asList(params); diff --git a/src/main/java/org/bukkit/craftbukkit/util/ServerShutdownThread.java b/src/main/java/org/bukkit/craftbukkit/util/ServerShutdownThread.java index b4a19d80bbf71591f25729fd0e98590350cb31d0..d752720f2f234b9dbd2117333fee1bfad663ec02 100644 --- a/src/main/java/org/bukkit/craftbukkit/util/ServerShutdownThread.java +++ b/src/main/java/org/bukkit/craftbukkit/util/ServerShutdownThread.java @@ -12,12 +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 org.spigotmc.AsyncCatcher.shuttingDown = true; // Paper + server.forceTicks = true; this.server.close(); + while (!server.hasFullyShutdown) Thread.sleep(1000); + } catch (InterruptedException e) { + e.printStackTrace(); + // Paper end } finally { 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 a142a56a920e153ed84c08cece993f10d76f7793..92d97a5810a379b427a99b4c63fb9844d823a84f 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) { 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 1ffb208094f521883ef0e23baf5fb29380b14273..4d271cae88c16ed2419f896c728fdff612540500 100644 --- a/src/main/java/org/spigotmc/WatchdogThread.java +++ b/src/main/java/org/spigotmc/WatchdogThread.java @@ -12,6 +12,7 @@ import org.bukkit.Bukkit; public class WatchdogThread extends Thread { + public static final boolean DISABLE_WATCHDOG = Boolean.getBoolean("disable.watchdog"); // Paper private static WatchdogThread instance; private long timeoutTime; private boolean restart; @@ -40,6 +41,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 @@ -71,12 +73,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 @@ -118,7 +121,7 @@ public class WatchdogThread extends Thread log.log( Level.SEVERE, "------------------------------" ); log.log( Level.SEVERE, "Server thread dump (Look for plugins here before reporting to Paper!):" ); // Paper com.destroystokyo.paper.io.chunk.ChunkTaskManager.dumpAllChunkLoadInfo(); // Paper - WatchdogThread.dumpThread( ManagementFactory.getThreadMXBean().getThreadInfo( MinecraftServer.getServer().serverThread.getId(), Integer.MAX_VALUE ), log ); + WatchdogThread.dumpThread( ManagementFactory.getThreadMXBean().getThreadInfo( server.serverThread.getId(), Integer.MAX_VALUE ), log ); log.log( Level.SEVERE, "------------------------------" ); // // Paper start - Only print full dump on long timeouts @@ -138,9 +141,25 @@ 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 + AsyncCatcher.shuttingDown = true; + 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 3dc317e466e1b93dff030794dd7f29ca1b266778..d285dbec16272db6b8a71865e05924ad66087407 100644 --- a/src/main/resources/log4j2.xml +++ b/src/main/resources/log4j2.xml @@ -1,5 +1,5 @@ - +