Improved logging.

* Now everything is logged as soon as the server starts, no more holding logs until bukkit initialization. * Now loggers follow the forge style of logging, this also applies to plugins * Added crucible option to show who is logging to System.out, now you can catch that annoying mod/plugin spamming nonsense in the console. * Added log4j context values for System.out calls, you can use %X{crucible-className} %X{crucible-methodName} and %X{crucible-lineNumber} on custom formatted logs for more precise information on what is directly printing to your logs * Added plugin prefix to colored console sender messages when logStdOutCaller is enabled This change can cause breaking issues to logging related things. More testing may be required.
CrucibleMC · May 5, 2023 · 5dd5521 · 5dd5521
1 parent 654d44b
commit 5dd5521
Show file tree

Hide file tree

Showing 11 changed files with 277 additions and 23 deletions.
diff --git a/patches/cpw/mods/fml/common/launcher/FMLServerTweaker.java.patch b/patches/cpw/mods/fml/common/launcher/FMLServerTweaker.java.patch
@@ -0,0 +1,10 @@
+--- ../src-base/minecraft/cpw/mods/fml/common/launcher/FMLServerTweaker.java
++++ ../src-work/minecraft/cpw/mods/fml/common/launcher/FMLServerTweaker.java
+@@ -19,6 +19,7 @@
+         classLoader.addTransformerExclusion("cpw.mods.fml.repackage.");
+         classLoader.addTransformerExclusion("cpw.mods.fml.relauncher.");
+         classLoader.addTransformerExclusion("cpw.mods.fml.common.asm.transformers.");
++        classLoader.addTransformerExclusion("io.github.crucible.bootstrap."); // Crucible - make our bootstrap stuff visible for both obfuscated and not obfuscated sides
+         classLoader.addClassLoaderExclusion("LZMA.");
+         FMLLaunchHandler.configureForServerLaunch(classLoader, this);
+         FMLLaunchHandler.appendCoreMods();
diff --git a/patches/cpw/mods/fml/relauncher/FMLRelaunchLog.java.patch b/patches/cpw/mods/fml/relauncher/FMLRelaunchLog.java.patch
@@ -0,0 +1,26 @@
+--- ../src-base/minecraft/cpw/mods/fml/relauncher/FMLRelaunchLog.java
++++ ../src-work/minecraft/cpw/mods/fml/relauncher/FMLRelaunchLog.java
+@@ -21,6 +21,7 @@
+ import org.apache.logging.log4j.ThreadContext;
+
+ import cpw.mods.fml.common.TracingPrintStream;
++import org.apache.logging.log4j.spi.LoggerContext;
+
+ public class FMLRelaunchLog {
+
+@@ -34,6 +35,7 @@
+     private static boolean configured;
+
+     private Logger myLog;
++    public LoggerContext ctx; // Crucible - Used to go nuclear down the line when merging bukkit and forge loggers
+
+     static Side side;
+
+@@ -47,6 +49,7 @@
+     private static void configureLogging()
+     {
+         log.myLog = LogManager.getLogger("FML");
++        log.ctx = LogManager.getContext(false); // Crucible - capture the context
+         ThreadContext.put("side", side.name().toLowerCase(Locale.ENGLISH));
+         configured = true;
+
diff --git a/patches/net/minecraft/server/dedicated/DedicatedServer.java.patch b/patches/net/minecraft/server/dedicated/DedicatedServer.java.patch
@@ -1,21 +1,34 @@
 --- ../src-base/minecraft/net/minecraft/server/dedicated/DedicatedServer.java
 +++ ../src-work/minecraft/net/minecraft/server/dedicated/DedicatedServer.java
-@@ -1,12 +1,12 @@
+@@ -1,19 +1,21 @@
  package net.minecraft.server.dedicated;
 
 +import co.aikar.timings.MinecraftTimings;
  import cpw.mods.fml.common.FMLCommonHandler;
++import cpw.mods.fml.relauncher.FMLRelaunchLog;
  import cpw.mods.fml.relauncher.Side;
  import cpw.mods.fml.relauncher.SideOnly;
 -import java.io.BufferedReader;
 +
  import java.io.File;
  import java.io.IOException;
 -import java.io.InputStreamReader;
++import java.lang.reflect.Field;
  import java.net.InetAddress;
  import java.net.Proxy;
- import java.util.ArrayList;
-@@ -34,9 +34,18 @@
+-import java.util.ArrayList;
+-import java.util.Collections;
+-import java.util.List;
+-import java.util.Random;
++import java.util.*;
+ import java.util.concurrent.Callable;
++
++import io.github.crucible.bootstrap.CrucibleServerMainHook;
++import io.github.crucible.util.CrucibleTracingLoggerOutputStream;
+ import net.minecraft.command.ICommandSender;
+ import net.minecraft.command.ServerCommand;
+ import net.minecraft.crash.CrashReport;
+@@ -34,9 +36,20 @@
  import net.minecraft.world.World;
  import net.minecraft.world.WorldSettings;
  import net.minecraft.world.WorldType;
@@ -25,16 +38,18 @@
 
 +// CraftBukkit start
 +import java.io.PrintStream;
++import java.util.concurrent.ConcurrentMap;
++
 +import org.apache.logging.log4j.Level;
 +
-+import org.bukkit.craftbukkit.LoggerOutputStream;
++import org.apache.logging.log4j.core.LoggerContext;
 +import org.bukkit.event.server.ServerCommandEvent;
 +// CraftBukkit end
 +
  @SideOnly(Side.SERVER)
  public class DedicatedServer extends MinecraftServer implements IServer
  {
-@@ -44,7 +53,7 @@
+@@ -44,7 +57,7 @@
      public final List pendingCommandList = Collections.synchronizedList(new ArrayList());
      private RConThreadQuery theRConThreadQuery;
      private RConThreadMain theRConThreadMain;
@@ -43,7 +58,7 @@
      private ServerEula field_154332_n;
      private boolean canSpawnStructures;
      private WorldSettings.GameType gameType;
-@@ -52,10 +61,13 @@
+@@ -52,10 +65,13 @@
      public static boolean allowPlayerLogins = false;
      private static final String __OBFID = "CL_00001784";
 
@@ -60,7 +75,7 @@
          {
              private static final String __OBFID = "CL_00001787";
              {
-@@ -82,31 +94,77 @@
+@@ -82,31 +98,102 @@
          };
      }
 
@@ -128,6 +143,7 @@
 +        }
 +
 +        global.addHandler(new org.bukkit.craftbukkit.util.ForwardLogHandler());
++
 +        final org.apache.logging.log4j.core.Logger logger = ((org.apache.logging.log4j.core.Logger) LogManager.getRootLogger());
 +
 +        for (org.apache.logging.log4j.core.Appender appender : logger.getAppenders().values())
@@ -138,14 +154,38 @@
 +            }
 +        }
 +
++        // Crucible start - go nuclear on all other loggers
++        try {
++            LoggerContext ctx = (LoggerContext) FMLRelaunchLog.log.ctx;
++            Field loggersField = LoggerContext.class.getDeclaredField("loggers");
++            loggersField.setAccessible(true);
++            @SuppressWarnings("unchecked")
++            ConcurrentMap<String, org.apache.logging.log4j.core.Logger> loggers =
++                    (ConcurrentMap<String, org.apache.logging.log4j.core.Logger>) loggersField.get(ctx);
++            for (org.apache.logging.log4j.core.Logger loggerToHack : loggers.values()) {
++                for (org.apache.logging.log4j.core.Appender appender : loggerToHack.getAppenders().values())
++                {
++                    if (appender instanceof org.apache.logging.log4j.core.appender.ConsoleAppender)
++                    {
++                        loggerToHack.removeAppender(appender);
++                    }
++                }
++            }
++        } catch (Throwable e) {
++            System.out.println("[Crucible] Unable to hack other loggers, expect broken and chaotic logs.");
++            e.printStackTrace();
++        }
++        // Crucible end
++
++        CrucibleServerMainHook.restoreStreams(); // Crucible - Restores the original streams so System.out does not log to forge logger
 +        new Thread(new org.bukkit.craftbukkit.util.TerminalConsoleWriterThread(System.out, this.reader)).start();
-+        System.setOut(new PrintStream(new LoggerOutputStream(logger, Level.INFO), true));
-+        System.setErr(new PrintStream(new LoggerOutputStream(logger, Level.WARN), true));
++        System.setOut(new PrintStream(new CrucibleTracingLoggerOutputStream(LogManager.getLogger("STDOUT"), Level.INFO), true));
++        System.setErr(new PrintStream(new CrucibleTracingLoggerOutputStream(LogManager.getLogger("STDERR"), Level.WARN), true));
 +        // CraftBukkit end 
          field_155771_h.info("Starting minecraft server version 1.7.10");
 
          if (Runtime.getRuntime().maxMemory() / 1024L / 1024L < 512L)
-@@ -117,7 +175,7 @@
+@@ -117,7 +204,7 @@
          FMLCommonHandler.instance().onServerStart(this);
 
          field_155771_h.info("Loading properties");
@@ -154,7 +194,7 @@
          this.field_154332_n = new ServerEula(new File("eula.txt"));
 
          if (!this.field_154332_n.func_154346_a())
-@@ -172,6 +230,18 @@
+@@ -172,6 +259,18 @@
                  this.setServerPort(this.settings.getIntProperty("server-port", 25565));
              }
 
@@ -173,7 +213,7 @@
              field_155771_h.info("Generating keypair");
              this.setKeyPair(CryptManager.createNewKeyPair());
              field_155771_h.info("Starting Minecraft server on " + (this.getServerHostname().length() == 0 ? "*" : this.getServerHostname()) + ":" + this.getServerPort());
-@@ -180,7 +250,7 @@
+@@ -180,7 +279,7 @@
              {
                  this.func_147137_ag().addLanEndpoint(inetaddress, this.getServerPort());
              }
@@ -182,7 +222,7 @@
              {
                  field_155771_h.warn("**** FAILED TO BIND TO PORT!");
                  field_155771_h.warn("The exception was: {}", new Object[] {ioexception.toString()});
-@@ -196,10 +266,17 @@
+@@ -196,10 +295,17 @@
                  field_155771_h.warn("To change this, set \"online-mode\" to \"true\" in the server.properties file.");
              }
 
@@ -202,7 +242,7 @@
 
              if (!PreYggdrasilConverter.func_152714_a(this.settings))
              {
-@@ -208,7 +285,8 @@
+@@ -208,7 +314,8 @@
              else
              {
                  FMLCommonHandler.instance().onServerStarted();
@@ -212,7 +252,7 @@
                  long j = System.nanoTime();
 
                  if (this.getFolderName() == null)
-@@ -274,11 +352,30 @@
+@@ -274,11 +381,30 @@
                      this.theRConThreadMain.startThread();
                  }
 
@@ -243,7 +283,7 @@
      public boolean canStructuresSpawn()
      {
          return this.canSpawnStructures;
-@@ -364,11 +461,19 @@
+@@ -364,11 +490,19 @@
 
      public void executePendingCommands()
      {

diff --git a/patches/org/bukkit/plugin/PluginLogger.java.patch b/patches/org/bukkit/plugin/PluginLogger.java.patch
@@ -0,0 +1,25 @@
+--- ../src-base/minecraft/org/bukkit/plugin/PluginLogger.java
++++ ../src-work/minecraft/org/bukkit/plugin/PluginLogger.java
+@@ -22,14 +22,20 @@
+     public PluginLogger(Plugin context) {
+         super(context.getClass().getCanonicalName(), null);
+         String prefix = context.getDescription().getPrefix();
+-        pluginName = prefix != null ? new StringBuilder().append("[").append(prefix).append("] ").toString() : "[" + context.getDescription().getName() + "] ";
++        // Crucible start - give plugins a proper prefix for log4j
++        //pluginName = prefix != null ? new StringBuilder().append("[").append(prefix).append("] ").toString() : "[" + context.getDescription().getName() + "] ";
++        pluginName = prefix != null ? prefix : context.getDescription().getName();
++        // Crucible end
+         setParent(context.getServer().getLogger());
+         setLevel(Level.ALL);
+     }
+
+     @Override
+     public void log(LogRecord logRecord) {
+-        logRecord.setMessage(pluginName + logRecord.getMessage());
++        // Crucible start - fix log4j prefix
++        //logRecord.setMessage(pluginName + logRecord.getMessage());
++        logRecord.setLoggerName(pluginName);
++        // Crucible end
+         super.log(logRecord);
+     }
+
diff --git a/patches/org/bukkit/plugin/SimplePluginManager.java.patch b/patches/org/bukkit/plugin/SimplePluginManager.java.patch
@@ -1,6 +1,22 @@
 --- ../src-base/minecraft/org/bukkit/plugin/SimplePluginManager.java
 +++ ../src-work/minecraft/org/bukkit/plugin/SimplePluginManager.java
-@@ -132,7 +132,9 @@
+@@ -40,6 +40,7 @@
+ public final class SimplePluginManager implements PluginManager {
+     private final Server server;
+     private final Map<Pattern, PluginLoader> fileAssociations = new HashMap<Pattern, PluginLoader>();
++    private final Set<PluginLoader> loaders = new HashSet<>(); // Crucible - used to look up plugins by class name
+     private final List<Plugin> plugins = new ArrayList<Plugin>();
+     private final Map<String, Plugin> lookupNames = new HashMap<String, Plugin>();
+     private static File updateDirectory = null;
+@@ -86,6 +87,7 @@
+         }
+
+         Pattern[] patterns = instance.getPluginFileFilters();
++        loaders.add(instance); // Crucible
+
+         synchronized (this) {
+             for (Pattern pattern : patterns) {
+@@ -132,7 +134,9 @@
              try {
                  description = loader.getPluginDescription(file);
                  String name = description.getName();
@@ -11,7 +27,7 @@
                      server.getLogger().log(Level.SEVERE, "Could not load '" + file.getPath() + "' in folder '" + directory.getPath() + "': Restricted Name");
                      continue;
                  } else if (description.rawName.indexOf(' ') != -1) {
-@@ -188,6 +190,9 @@
+@@ -188,6 +192,9 @@
              }
          }
 
@@ -21,7 +37,7 @@
          while (!plugins.isEmpty()) {
              boolean missingDependency = true;
              Iterator<String> pluginIterator = plugins.keySet().iterator();
-@@ -555,7 +560,8 @@
+@@ -555,7 +562,8 @@
              throw new IllegalPluginAccessException("Plugin attempted to register " + event + " while not enabled");
          }
 
@@ -31,7 +47,7 @@
              getEventListeners(event).register(new TimedRegisteredListener(listener, executor, priority, plugin, ignoreCancelled));
          } else {
              getEventListeners(event).register(new RegisteredListener(listener, executor, priority, plugin, ignoreCancelled));
-@@ -716,7 +722,7 @@
+@@ -716,7 +724,7 @@
      }
 
      public boolean useTimings() {
@@ -40,7 +56,7 @@
      }
 
      /**
-@@ -725,6 +731,19 @@
+@@ -725,6 +733,23 @@
       * @param use True if per event timing code should be used
       */
      public void useTimings(boolean use) {
@@ -59,5 +75,9 @@
 +        return plugin;
 +    }
 +
++    public Set<PluginLoader> getLoaders() {
++        return loaders;
++    }
++
 +    //Crucible end
  }
diff --git a/patches/org/bukkit/plugin/java/JavaPluginLoader.java.patch b/patches/org/bukkit/plugin/java/JavaPluginLoader.java.patch
@@ -149,6 +149,15 @@
      public PluginDescriptionFile getPluginDescription(File file) throws InvalidDescriptionException {
          Validate.notNull(file, "File cannot be null");
 
+@@ -178,7 +215,7 @@
+         return fileFilters.clone();
+     }
+
+-    Class<?> getClassByName(final String name) {
++    public Class<?> getClassByName(final String name) {
+         Class<?> cachedClass = classes.get(name);
+
+         if (cachedClass != null) {
 @@ -283,8 +320,9 @@
                  }
              }

diff --git a/src/main/java/io/github/crucible/CrucibleConfigs.java b/src/main/java/io/github/crucible/CrucibleConfigs.java
@@ -146,6 +146,10 @@ public class CrucibleConfigs extends YamlConfig {
     @Comment("Log Material injections.")
     public boolean crucible_logging_logMaterialInjection = false;
 
+    @Comments({"Log the plugin/caller as prefix on System.out usages, no more mysterious console usages.",
+            "Be warned that looking up the caller can have a noticeable performance impact."})
+    public boolean crucible_logging_logStdOutCaller = false;
+
     @Comment("List of world names where the usage of modded itens and blocks will be disabled for ")
     public List<String> crucible_protectedWorld = Collections.singletonList("spawn");
 

diff --git a/src/main/java/io/github/crucible/bootstrap/CrucibleServerMainHook.java b/src/main/java/io/github/crucible/bootstrap/CrucibleServerMainHook.java
@@ -5,6 +5,7 @@
 import java.io.File;
 import java.io.FileReader;
 import java.io.IOException;
+import java.io.PrintStream;
 import java.nio.file.Files;
 import java.nio.file.Path;
 import java.nio.file.Paths;
@@ -22,6 +23,8 @@ public class CrucibleServerMainHook {
             "https://repo.maven.apache.org/maven2/"
     };
     private static final Path LIBRARY_ROOT = Paths.get("libraries").toAbsolutePath();
+    public static final PrintStream originalOut = System.out;
+    public static final PrintStream originalErr = System.err;
 
     public static void relaunchMain(String[] args) throws Exception {
         System.out.println("[Crucible] Running pre-launch tweaks");
@@ -79,4 +82,9 @@ private static void setupLibraries() throws InterruptedException {
         LibraryManager.downloadMavenLibraries(LIBRARY_ROOT, Stream.of(REPOS, userDefinedRepos).flatMap(Stream::of)
                 .filter(s -> !s.isEmpty()).toArray(String[]::new), CrucibleMetadata.NEEDED_LIBRARIES);
     }
+
+    public static void restoreStreams() {
+        System.setOut(originalOut);
+        System.setErr(originalErr);
+    }
 }