Resource Enable debug logging to console

Discussion in 'Spigot Plugin Development' started by UniverseCraft, Aug 5, 2020.

  1. Hi all,

    It's long been an open problem in the Bukkit/Spigot community as to how to log debug messages to the console without some hacky workarounds like
    Code (Text):
    [21:47:05 INFO]: [DEBUG] A debug message
    (The problem with these is that they still log at the INFO level, aren't as easy to parse, and look ugly.)

    Today, I'm going to explain what causes this problem and how to fix it, and I will provide a convenience class that you can drop into any project to easily enable debug logging to the console. By the end of this, you'll be able to get nice-looking debug messages like
    Code (Text):
    [21:47:05 DEBUG]: A debug message
    or
    Code (Text):
    [21:47:05] [Server thread/DEBUG]: A more detailed debug message
    When you log something in Java, there are two main components: the message and the level. The level defines how "verbose" the message is, or the level of detail. You may be familiar with the most common levels: SEVERE, WARNING, and INFO (these appear in the console as ERROR, WARN, and INFO, respectively.)

    But there are four more levels intended for providing debug or diagnostic information: CONFIG, FINE, FINER, and FINEST (in the console these appear as DEBUG and TRACE.)

    For example, you might want to send a debug message whenever a user is denied access to a command:
    Code (Java):
    if(!player.hasPermission("my.command.permission")) {
      LOGGER.fine("Player " + player.getName() + " failed permission check my.command.permission");
      return true;
    }
    When debug logging becomes a habit, it can be incredibly useful in quickly finding the cause of problems without needing to try to replicate the error yourself, attach a debugger, analyze crash reports, or guess.

    The problem
    For non-debug log levels, changing the log level is as trivial as getLogger().setLevel(newLevel);.
    But try setting the level to FINE and logging a message on that level. It won't show up in the console. (You can get it to show up in the logs by setting "debug" in server.properties to true, but it won't show up in the console.)

    Why you can't log debug messages to the console
    There are two different logging subsystems that Bukkit uses. The first one is in the java.util.logging package, which we'll abbreviate to JUL. The other one is in the org.apache.logging.log4j package, which we'll abbreviate to Log4j.

    Note: JUL and Log4j use different log level names.
    JUL => Log4j
    OFF => OFF
    SEVERE => ERROR
    WARNING => WARN
    INFO => INFO
    CONFIG => DEBUG
    FINE => TRACE
    FINER => TRACE
    FINEST => TRACE
    ALL => ALL


    The Bukkit API exposes a JUL logger to each plugin, which is what you get with JavaPlugin#getLogger(). But in fact this is just a facade for an underlying chain of Log4j loggers.

    More specifically, the JUL Logger#log method sends the log message through the CraftBukkit class ForwardLogHandler which routes it to a Log4j logger.

    You might be wondering - can't we change the level of the Log4j logger too?

    Well, no, but actually yes, but actually no. Allow me to explain. Log4j is not bundled with the Spigot API, so you need to add craftbukkit.jar as a dependency as well. This is crippling for multi-version projects, where each module would then need to implement the code separately despite the fact that it is the same for each project. (You could also add log4j itself, but then you can't add craftbukkit without facing potential duplication errors.)

    However, with a little work, we can in fact set the log level of the Log4j loggers. The problem is, the message still doesn't go to the console. This is where most past efforts to solve this issue have given up.

    To find the root cause of the problem, we have to look inside a file inside craftbukkit.jar called log4j2.xml. This file is a hard-wired configuration for log4j, and it contains this very frustrating line:
    Code (XML):
    <AppenderRef ref="TerminalConsole" level="info"/>
    This means that anything output to the console will be filtered out if it doesn't have at least level INFO.

    Fortunately, there are two ways to override this. The first is to create a duplicate configuration file and change all the log levels to "trace". For this to work, you need to add the flag
    -Dlog4j.configurationFile="log4j2edited.xml" to your run script (replacing log4j2edited.xml with your new file name, which should be in the same directory as your run script).
    The problem with this is that it inexplicably breaks some internal functionality and can disable certain console features like colors and the cursor. You'll also get a lot of irrelevant debug information, for example from the security manager and network manager, which tend to complain a lot on the DEBUG level.

    The other way is to remove the console appender on the root log4j logger.

    When a message comes into a log4j logger, it is routed through every registered appender. Appenders have the task of actually carrying out the logging. For example, in Minecraft there is one appender which writes to the log file and another which writes to the console. Appenders allow the logger to decouple the act of logging from the physical media to which information is logged, and allow specifying different formats, log levels, etc. per appender.

    Unfortunately, appenders can also independently filter out messages that don't meet their internal criteria. In this case, the TerminalConsole appender filters out messages with a level lower than INFO.

    Removing the appender and replacing it with a debug-friendly appender can become tedious (and relies on unsupported APIs). We have to create our own log filters, create our own appenders, and in the process scoop up some additional dependencies, some of which (like craftbukkit) are version dependent. And this has a tendency to break between versions - what works on Paper doesn't work on Spigot, and vice versa.

    The solution
    Solving this problem in a relatively version-independent way requires two realizations:
    1) It's possible and in fact easier and less error-prone to manage debug logging with JUL Handlers than with Log4j Appenders.
    2) It's possible to log raw text directly to the console, completely bypassing log4j.

    In essence, here's the default path from log request to console:
    [​IMG]

    And here's how we bypass it:
    [​IMG]
    By only working with the JUL API as opposed to the log4j API, there's a lower probability of wrecking internals since we're operating mainly at a higher level of abstraction.


    Utilizing a little reflection, we can bypass the need for any external libraries, and bypass the need for log4j entirely.

    First, we need to get the handle to the raw java.io.Writer that Java uses to write to the console. (This is at a lower level of abstraction than the appenders.)

    Conveniently, this is stored as the field "out" in the field "reader" of the field "console" in the CraftServer-casted version of Bukkit#getServer(). Let's break that down:
    1. Bukkit#getServer() to get the server
    2. Use reflection to cast to CraftServer
    3. Reflect the console field from the CraftServer, of type MinecraftServer
    4. Reflect the reader field from the MinecraftServer, of type OBC.libs.jline.console.ConsoleReader
    5. Reflect the out field from the ConsoleReader, of type Writer
    Then we create a Handler which we add to the global JUL logger (via Logger#getLogger("")). We override the publish(LogRecord) method to do the following:
    1. Return out of any non-debug messages (i.e. higher than level CONFIG)
    2. Return out of any messages whose levels do not meet the level of the logger
      1. This gets a bit hairy, since plugins use a specialized JUL logger subclass PluginLogger which is not reachable via Logger#getLogger. A workaround is presented in the attached solution class.
    3. Write to the Writer (the out field we got above)
      1. To make things a little neater, we can also utilize some methods from the ConsoleReader (the reader field) which will keep the terminal functionality (mostly) intact.
      2. We can largely copy this from the OBC.util.TerminalConsoleWriterThread#run() method, which handles this normally.

    Okay, how do I enable this for my plugin?
    It's simple! I've created a self-contained class that only relies on the Spigot API which will accomplish all of this for you. Simply drop the linked DebugLoggingProvider class into your project and call new DebugLoggingProvider().enableDebugLogging() in your plugin's onLoad.

    (For 1.14+, you can use the newer logging format with new DebugLoggingProvider().enableDebugLogging(Level.INFO, true).

    Note that this only enables debug logging for JUL loggers. If you use log4j, you'll have to go the route of a custom log4j configuration as I described above.

    Here's the class, tested on Spigot 1.8.8 through 1.16.1: https://gist.github.com/UniverseCraft/cfd2b30c915c7ad7828009559ff036ff
     
    • Like Like x 2
    • Useful Useful x 2
  2. Can you show an example of how to send a debug message with this? I didn’t understand everything right away but I’d find it interesting to use this.
     
  3. Interesting resource.

    After you enable UniverseCraft’s DebugLoggingProvider class and such, use
    Code (Java):
    yourJavaPluginInstance.getLogger().log(Level.CONFIG, “debug message here”);
     
    • Like Like x 1
    • Agree Agree x 1