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 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 d7995cadda8f48bbf642114935311180d3ebde5b..226cba0c1eeedd9e80acd603c46b802c183db1fa 100644 --- a/src/main/java/net/minecraft/CrashReport.java +++ b/src/main/java/net/minecraft/CrashReport.java @@ -230,6 +230,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 0fa1d9f299194ff660130a1cf33d9a405d56a842..d50878653132218dd494e0e5ed6fc3a32d4f1465 100644 --- a/src/main/java/net/minecraft/server/MinecraftServer.java +++ b/src/main/java/net/minecraft/server/MinecraftServer.java @@ -291,7 +291,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; @@ -302,6 +302,9 @@ public abstract class MinecraftServer extends ReentrantBlockableEventLoop S spin(Function serverFactory) { AtomicReference atomicreference = new AtomicReference(); Thread thread = new Thread(() -> { @@ -858,6 +861,7 @@ public abstract class MinecraftServer extends ReentrantBlockableEventLoop {}; + } + // Paper end return new TickTask(this.tickCount, runnable); } @@ -1451,6 +1505,7 @@ public abstract class MinecraftServer extends ReentrantBlockableEventLoop 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 495ab82a3a9d47583eb7239730aa78dd51f16fc6..8b0c85d341c75e86421fc7c72aefcce83a165075 100644 --- a/src/main/java/net/minecraft/world/level/Level.java +++ b/src/main/java/net/minecraft/world/level/Level.java @@ -896,6 +896,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 f229838bf0566d61b2716463ff95fcc0b04d2e97..c9a6a56dfd25601bc0a11e5ddb349dba372c0e18 100644 --- a/src/main/java/net/minecraft/world/level/chunk/LevelChunk.java +++ b/src/main/java/net/minecraft/world/level/chunk/LevelChunk.java @@ -1091,6 +1091,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/Main.java b/src/main/java/org/bukkit/craftbukkit/Main.java index 8c9a6e1b34865c3a15eea40637d6a4b540396a5c..c561677e81095ab6735d81a414a249838b135f7a 100644 --- a/src/main/java/org/bukkit/craftbukkit/Main.java +++ b/src/main/java/org/bukkit/craftbukkit/Main.java @@ -178,6 +178,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) { @@ -288,8 +318,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(net.minecraft.world.level.lighting.LayerLightEventListener.DummyLightLayerEventListener.class.getName()); + tryPreloadClass(net.minecraft.world.level.lighting.LayerLightEventListener.class.getName()); + tryPreloadClass(net.minecraft.util.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 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 14eadb0f81dfad072d82d7793cce1a4dd3f2c5f0..29b39dff0aceaa902f701162a42d3f2f881d6d5a 100644 --- a/src/main/java/org/spigotmc/RestartCommand.java +++ b/src/main/java/org/spigotmc/RestartCommand.java @@ -138,7 +138,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 06efdd7aa6d35a670e81c4f303618a7ba301396a..e71041d41eae31cce73d8817c4f95f16c8c600aa 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 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 ea4e2161c0bd43884055cc6b8d70b2139f70e720..266b4e6fb3988b5848021c83fdc68e342c70b188 100644 --- a/src/main/resources/log4j2.xml +++ b/src/main/resources/log4j2.xml @@ -1,5 +1,5 @@ - +