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 f2a0a9f5d86820ce8098301256d2faf3d1a7c697..8a19c96499c22f0d4705613ffec38d5677e1a72d 100644 --- a/src/main/java/com/destroystokyo/paper/Metrics.java +++ b/src/main/java/com/destroystokyo/paper/Metrics.java @@ -86,6 +86,9 @@ public class Metrics { timer.scheduleAtFixedRate(new TimerTask() { @Override public void run() { + if (MinecraftServer.getServer().hasStopped()) { + return; + } submitData(); } }, 1000 * 60 * 5, 1000 * 60 * 30); diff --git a/src/main/java/net/minecraft/server/CrashReport.java b/src/main/java/net/minecraft/server/CrashReport.java index 95e6a6de7ccfc4445d0ac19c5f874c0d533b1712..cc6e6f245ee5e73bd570cf42381bf55ee0b364d3 100644 --- a/src/main/java/net/minecraft/server/CrashReport.java +++ b/src/main/java/net/minecraft/server/CrashReport.java @@ -257,6 +257,7 @@ public class CrashReport { } public static CrashReport a(Throwable throwable, String s) { + if (throwable instanceof ThreadDeath) com.destroystokyo.paper.util.SneakyThrow.sneaky(throwable); // Paper while (throwable instanceof CompletionException && throwable.getCause() != null) { throwable = throwable.getCause(); } diff --git a/src/main/java/net/minecraft/server/DedicatedServer.java b/src/main/java/net/minecraft/server/DedicatedServer.java index fa72eae6befb9d05244b65bcaaed35e9fb492027..03b38e2c53376db25864a0c6f00f786c4dae215d 100644 --- a/src/main/java/net/minecraft/server/DedicatedServer.java +++ b/src/main/java/net/minecraft/server/DedicatedServer.java @@ -238,7 +238,7 @@ public class DedicatedServer extends MinecraftServer implements IMinecraftServer long j = SystemUtils.getMonotonicNanos() - 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.GameRuleBoolean) this.getGameRules().get(GameRules.ANNOUNCE_ADVANCEMENTS)).a(dedicatedserverproperties.announcePlayerAchievements, (MinecraftServer) this); } @@ -362,6 +362,7 @@ public class DedicatedServer extends MinecraftServer implements IMinecraftServer //this.remoteStatusListener.b(); // Paper - don't wait for remote connections } + hasFullyShutdown = true; // Paper System.exit(0); // CraftBukkit } @@ -695,7 +696,7 @@ public class DedicatedServer extends MinecraftServer implements IMinecraftServer @Override public void stop() { super.stop(); - SystemUtils.h(); + //SystemUtils.h(); // Paper - moved into super } @Override diff --git a/src/main/java/net/minecraft/server/IAsyncTaskHandler.java b/src/main/java/net/minecraft/server/IAsyncTaskHandler.java index c475009fe03a1550cb64a716a02a5a8b5204c873..5df6be7e8d9b1295ed0700b3be90c3778fc7d77c 100644 --- a/src/main/java/net/minecraft/server/IAsyncTaskHandler.java +++ b/src/main/java/net/minecraft/server/IAsyncTaskHandler.java @@ -135,6 +135,7 @@ public abstract class IAsyncTaskHandler implements Mailbox S a(Function function) { AtomicReference atomicreference = new AtomicReference(); Thread thread = new Thread(() -> { @@ -735,6 +737,7 @@ public abstract class MinecraftServer extends IAsyncTaskHandlerReentrant {}; + } + // Paper end return new TickTask(this.ticks, runnable); } @@ -1305,6 +1357,7 @@ public abstract class MinecraftServer extends IAsyncTaskHandlerReentrant { CompletableFuture completablefuture; diff --git a/src/main/java/net/minecraft/server/PlayerList.java b/src/main/java/net/minecraft/server/PlayerList.java index bf8df178256e5eebbdadfd53e2f0edbfced0aba3..f76bbac925aef6d1e917195ed2f2b4da1d3d7b52 100644 --- a/src/main/java/net/minecraft/server/PlayerList.java +++ b/src/main/java/net/minecraft/server/PlayerList.java @@ -429,7 +429,7 @@ public abstract class PlayerList { cserver.getPluginManager().callEvent(playerQuitEvent); entityplayer.getBukkitEntity().disconnect(playerQuitEvent.getQuitMessage()); - entityplayer.playerTick(); // SPIGOT-924 + if (server.isMainThread()) entityplayer.playerTick(); // 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/server/SystemUtils.java b/src/main/java/net/minecraft/server/SystemUtils.java index 1fe1df445ba56b2f176ee25502a774aa0a7bd00b..916a6a1fc1ccc73e4fb974ad77310d16fd8bd7e6 100644 --- a/src/main/java/net/minecraft/server/SystemUtils.java +++ b/src/main/java/net/minecraft/server/SystemUtils.java @@ -123,6 +123,7 @@ public class SystemUtils { return SystemUtils.f; } + public static void shutdownServerThreadPool() { h(); } // Paper - OBFHELPER public static void h() { a(SystemUtils.e); a(SystemUtils.f); diff --git a/src/main/java/net/minecraft/server/World.java b/src/main/java/net/minecraft/server/World.java index df7386a8356e7191dfa06b3ab59537c13cc6ff9b..df6299d81a6d6450272b9aaba397df523cb9e862 100644 --- a/src/main/java/net/minecraft/server/World.java +++ b/src/main/java/net/minecraft/server/World.java @@ -797,6 +797,7 @@ public abstract class World implements GeneratorAccess, AutoCloseable { gameprofilerfiller.exit(); } catch (Throwable throwable) { + if (throwable instanceof ThreadDeath) throw throwable; // Paper // Paper start - Prevent tile entity and entity crashes String msg = "TileEntity threw exception at " + tileentity.world.getWorld().getName() + ":" + tileentity.position.getX() + "," + tileentity.position.getY() + "," + tileentity.position.getZ(); System.err.println(msg); @@ -872,6 +873,7 @@ public abstract class World implements GeneratorAccess, AutoCloseable { try { consumer.accept(entity); } catch (Throwable throwable) { + if (throwable instanceof ThreadDeath) throw throwable; // Paper // Paper start - Prevent tile entity and entity crashes String msg = "Entity threw exception at " + entity.world.getWorld().getName() + ":" + entity.locX() + "," + entity.locY() + "," + entity.locZ(); System.err.println(msg); diff --git a/src/main/java/org/bukkit/craftbukkit/CraftServer.java b/src/main/java/org/bukkit/craftbukkit/CraftServer.java index b86eb9afb170b8a827ce3f6c85de08c75f260b14..dec85293caeaf247ef58975f1f7dfd2bb095635d 100644 --- a/src/main/java/org/bukkit/craftbukkit/CraftServer.java +++ b/src/main/java/org/bukkit/craftbukkit/CraftServer.java @@ -1788,7 +1788,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 } @Override diff --git a/src/main/java/org/bukkit/craftbukkit/Main.java b/src/main/java/org/bukkit/craftbukkit/Main.java index 2befc5904249abb0461bac3305186de728d5b81d..99efa63857dd3fb0a7d488937519ac225e379913 100644 --- a/src/main/java/org/bukkit/craftbukkit/Main.java +++ b/src/main/java/org/bukkit/craftbukkit/Main.java @@ -150,6 +150,37 @@ public class Main { OptionSet options = null; + // Paper start - preload logger classes to avoid plugins mixing versions + tryPreloadClass("com.destroystokyo.paper.log.LogFullPolicy"); + tryPreloadClass("org.apache.logging.log4j.core.Core"); + 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.ThrowableProxy$CacheEntry"); + 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) { @@ -245,8 +276,65 @@ 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.AbstractChannelHandlerContext$13"); + 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.server.LightEngineLayerEventListener$Void"); + tryPreloadClass("net.minecraft.server.LightEngineLayerEventListener"); + tryPreloadClass("net.minecraft.server.ExceptionSuppressor"); + // 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 449e99d1b673870ed6892f6ab2c715a2db35c35d..c7ed6e0f8a989cec97700df2b15198c9c481c549 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; 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 aefea3a9a8b9b75c62bd20018be7cd166a213001..123de5ac9026508e21cdc225f0962f5c3c46fed5 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 5bdcdcf9e85b73086722783bff26321d03382bb9..513c1041c34ebb3ac1775674a3f4526693759c08 100644 --- a/src/main/java/org/spigotmc/WatchdogThread.java +++ b/src/main/java/org/spigotmc/WatchdogThread.java @@ -13,6 +13,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 final long timeoutTime; private final long earlyWarningEvery; // Paper - Timeout time for just printing a dump but not restarting @@ -41,6 +42,7 @@ public class WatchdogThread extends Thread { if ( instance == null ) { + if (timeoutTime <= 0) timeoutTime = 300; // Paper instance = new WatchdogThread( timeoutTime * 1000L, restart ); instance.start(); } @@ -67,12 +69,13 @@ public class WatchdogThread extends Thread // Paper start Logger log = Bukkit.getServer().getLogger(); long currentTime = monotonicMillis(); - if ( lastTick != 0 && currentTime > lastTick + earlyWarningEvery && !Boolean.getBoolean("disable.watchdog") ) + MinecraftServer server = MinecraftServer.getServer(); + if (lastTick != 0 && hasStarted && (!server.isRunning() || (currentTime > lastTick + earlyWarningEvery && !DISABLE_WATCHDOG) )) { - 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 @@ -114,7 +117,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 ChunkTaskManager.dumpAllChunkLoadInfo(); // Paper - dumpThread( ManagementFactory.getThreadMXBean().getThreadInfo( MinecraftServer.getServer().serverThread.getId(), Integer.MAX_VALUE ), log ); + dumpThread( ManagementFactory.getThreadMXBean().getThreadInfo( server.serverThread.getId(), Integer.MAX_VALUE ), log ); log.log( Level.SEVERE, "------------------------------" ); // // Paper start - Only print full dump on long timeouts @@ -135,9 +138,24 @@ public class WatchdogThread extends Thread if ( isLongTimeout ) { - if ( 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.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 476f4a5cbe664ddd05474cb88553018bd334a5b8..8af159abd3d0cc94cf155fec5b384c42f69551bf 100644 --- a/src/main/resources/log4j2.xml +++ b/src/main/resources/log4j2.xml @@ -1,5 +1,5 @@ - +