Allow plugins to use SLF4J for logging #890

stephan-gh · 2017-09-21T16:49:30Z

This is a set of 3 commits to improve the logging implementation of Paper and allow plugins to use SLF4J as alternative logging API. The exact changes and the reasoning for them is explained in the commit messages (either directly or in the patches) so I'm not going to repeat everything here.

SLF4J is a commonly used abstraction for various logging frameworks and it is the easiest way to handle logging in an implementation-agnostic way. It is also used by many Java libraries as logging abstraction. I intend to create a similar PR for Waterfall so eventually, the same logging API can be used on Paper, Waterfall, Sponge and other modding APIs.

The primary difficulty to make this work was to move the plugin prefixes out of a custom JUL PluginLogger implementation and handle them directly in the underlying logging framework (Log4J). Otherwise, messages logged with SLF4J would be missing the plugin prefix.

The solution is pretty simple: Use the plugin name as logger name and make it visible in the log using the Log4J configuration. Hide the logger name for Minecraft and Paper log messages to make it less verbose.

kashike · 2017-09-21T16:50:35Z

Spigot-API-Patches/0067-Handle-plugin-prefixes-in-implementation-logging-con.patch

+     private FileConfiguration newConfig = null;
+     private File configFile = null;
+-    private PluginLogger logger = null;
+    private Logger logger = null; // Paper: PluginLogger -> Logger


// Paper - PluginLogger -> Logger

kashike · 2017-09-21T16:50:44Z

Spigot-API-Patches/0067-Handle-plugin-prefixes-in-implementation-logging-con.patch

+         this.classLoader = classLoader;
+         this.configFile = new File(dataFolder, "config.yml");
+-        this.logger = new PluginLogger(this);
+        this.logger = Logger.getLogger(description.getName()); // Paper: Handle plugin prefix in implementation


// Paper - Handle plugin prefix in implementation

kashike · 2017-09-21T16:51:12Z

Spigot-Server-Patches/0238-Use-Log4j-IOStreams-to-redirect-System.out-err-to-lo.patch

+             <scope>runtime</scope>
+         </dependency>
+
+        <!-- Paper: Add additional Log4J dependencies -->


kashike · 2017-09-21T16:51:46Z

Spigot-Server-Patches/0239-Handle-plugin-prefixes-using-Log4J-configuration.patch

+                                 </relocation>
+                             </relocations>
+                             <transformers>
+                                <!-- Paper: Exclude log4j2-test.xml -->


kashike · 2017-09-21T16:52:00Z

Spigot-API-Patches/0068-Allow-plugins-to-use-SLF4J-for-logging.patch

+             <scope>compile</scope>
+         </dependency>
+
+        <!-- Paper: Add SLF4J -->


kashike · 2017-09-21T16:52:12Z

Spigot-Server-Patches/0239-Handle-plugin-prefixes-using-Log4J-configuration.patch

+     {
+         playerSample = getInt( "settings.sample-count", 12 );
+-        System.out.println( "Server Ping Player Sample Count: " + playerSample );
+        Bukkit.getLogger().log( Level.INFO, "Server Ping Player Sample Count: {0}", playerSample ); // Paper: Use logger


// Paper - Use logger

kashike · 2017-09-21T16:54:06Z

Have you tested this with some popular plugins, such as WorldEdit and EssentialsX?

stephan-gh · 2017-09-21T16:55:39Z

@kashike I tested this with the incredibly popular Bukkittest plugin: https://gist.github.com/Minecrell/4de33b1b007dba9ce037907cd573c898. I'm sure it has at least as many downloads as Essentials and WorldEdit...

kashike · 2017-09-21T17:14:13Z

Spigot-API-Patches/0067-Handle-plugin-prefixes-in-implementation-logging-con.patch

+         this.classLoader = classLoader;
+         this.configFile = new File(dataFolder, "config.yml");
+-        this.logger = new PluginLogger(this);
+        this.logger = Logger.getLogger(description.getName()); // Paper: Handle plugin prefix in implementation


Should be getPrefix().

stephan-gh · 2017-09-21T18:00:41Z

@kashike All fixed.

I tested with Essentials and WorldEdit and after some work log messages are now visible. Essentials needs a workaround because it uses the Essentials logger internally instead of the plugin logger, and redirects its messages to the plugin logger by setting that as a parent. However, since the main plugin logger is now also called Essentials this results in an infinite loop. Fixed that by disallowing plugins to modify the parent of the plugin logger. (The warning can be avoided in Essentials by checking if getLogger() == LOGGER ).

WorldEdit works correctly but it doesn't use the plugin logger either so a different logger name is displayed in some cases.

Example log: https://gist.github.com/Minecrell/53eb99d4e06eb006b30f7a67decd7be9#file-gistfile1-txt-L104-L119

stephan-gh · 2017-09-21T18:47:59Z

Tested a "few" more plugins. All plugins are working but mostly older, large plugins bypass the plugin logger entirely and add the plugin prefix manually. Some of these plugins (marked with ❗️) will now show the full qualified logger name additionally. We could white-list the packages manually as a workaround...

[20:47:26] [Server thread/INFO] [com.sk89q.worldguard.bukkit.WorldConfiguration]: [WorldGuard] (world) TNT ignition is PERMITTED.

Essentials: ✔️ Added workaround (see comment above)
WorldEdit: ❗️ Doesn't use plugin logger, full qualified logger name is shown additionally.
WorldGuard: ❗️ Like WorldEdit
PermissionsEx: ❗️ Like WorldEdit
Vault: ✔️ Plugin main class / (✔️) Hooks, like Multiverse-Core
ProtocolLib: ✔️
ServerListPlus: ✔️ (Great plugin, would recommend it)
ViaVersion: ✔️
TitleManager: ❓ Doesn't log anything after starting the server
LuckPerms: (✔️) Uses colored output and bypasses logger entirely
GriefPrevention: ✔️
Multiverse-Core: (✔️) Uses Minecraft logger instead of plugin logger and adds plugin prefix manually. Prefix is shown after the : (like always without this PR), works correctly otherwise:
```
[20:36:45 INFO] [Multiverse-Core]: Enabling Multiverse-Core v2.5-b719
[20:36:45 INFO]: [Multiverse-Core] Version 2.5-b719 (API v20) Enabled
```
Citizens: (✔️) Like Multiverse-Core
VoxelSniper: ✔️
NoCheatPlus: (✔️) Like Multiverse-Core
PlaceholderAPI: ✔️
ASkyBlock: ✔️
Dynmap: ✔️
BuycraftX: ✔️

stephan-gh · 2017-09-22T07:50:54Z

I disabled the logger prefix manually for com.sk89q.* and ru.tehkode.* so the messages logged by WorldEdit, WorldGuard and PermissionsEx now show up correctly in the log. Adding exclusions for specific plugins is annoying but since these are the only plugins with this problem (at least from the ones I've tested) it might be the best way to fix them.

The implementation in this PR works correctly, it's only plugins that bypass the plugin loggers which may cause issues.

kashike · 2017-09-22T08:46:27Z

Could you provide an updated log, please?

stephan-gh · 2017-09-22T09:01:16Z

@kashike I could. Maybe I will... Actually, why not? https://gist.github.com/Minecrell/35f5dbb69eefaa3137daece6224588a4

stephan-gh · 2017-09-22T09:09:25Z

@kashike Log with latest Paper build without my changes: https://gist.github.com/Minecrell/daa3e038f47751ed380fba661d3def73

stephan-gh · 2017-09-22T11:40:45Z

Opened similar PR for Waterfall: PaperMC/Waterfall#176

stephan-gh · 2017-09-22T19:25:26Z

Moved plugin prefix back to behind the : as discussed in #paper so it now looks pretty much like before: https://gist.github.com/Minecrell/97145ddccc0062eb7c2f84152caffb50

Log4j2 provides an optimized implementation of PrintStream that redirects its output to a logger. Use it instead of a custom implementation for minor performance improvements and some fixes. With the old implementation, each call to System.print() results in a separate line, even though it should not result in a line break. Log4j's implementation handles it correctly.

SLF4J is a commonly used abstraction for various logging frameworks such as java.util.logging (JUL) or Log4j. Currently, plugins are required to do all their logging using the provided JUL logger. This is annoying for plugins that target multiple platforms or when using libraries that log messages using SLF4J. Expose SLF4J as optional logging API for plugins, so they can use it without having to shade it in the plugin and going through several layers of logging abstraction.

Essentials uses a custom logger name ("Essentials") instead of the plugin logger. Log messages are redirected to the plugin logger by setting the parent of the "Essentials" logger to the plugin logger. With our changes, the plugin logger is now also called "Essentials", resulting in an infinite loop. Make sure plugins can't change the parent of the plugin logger to avoid this.

Some plugins bypass the plugin logger and add the plugin prefix manually to the log message. Since they use other logger names (e.g. qualified class names) these would now also appear in the log. Disable the logger prefix for these plugins so the messages show up correctly.

kashike · 2017-09-23T19:56:57Z

kashike · 2017-09-23T19:57:07Z

Thanks, @Minecrell.

SLF4J-over-Log4j2 is not needed anymore as of PaperMC/Paper#890

mibby · 2017-09-26T11:49:30Z

Noticed a plugin merging start-up logging verbose with world loading verbose on a single line whereas it didn't before.

2nd line in particular.

[04:07:22] [Server thread/INFO]: [LibsDisguises] Discovered nms version: v1_12_R1
[04:07:23] [Server thread/INFO]: [DabCore] Attempting to load default ItemUtils[DabCore] Loaded default, enjoy :)Preparing start region for level 3 (Seed: -1991970816273548549)[LibsDisguises] Loaded 0 custom disguises
[04:07:23] [Server thread/INFO]: [ConditionalCommands] Enabling ConditionalCommands v1.4

Other than that, just EssentialsX whining.

[04:07:29] [Server thread/WARN]: [Essentials] Ignoring attempt to change parent of plugin logger

stephan-gh · 2017-09-26T13:14:29Z

@mibby That's because DabCore does wonderful logging using System.out.print instead of either using a logger(!!) or inserting a new line (e.g. using println). Spigot handles this incorrectly, and I fixed it in this PR. Not sure if we should revert it just to keep incorrect behavior and to encourage plugins to continue using System.out for logging.......

The Essentials warning is unrelated but can be fixed easily in Essentials. I will try to submit a PR to fix it when I have time, but until then it's just a warning, nothing breaks due to it.

SLF4J logging for plugins is a feature introduced in PaperMC/Paper#890. Plugins should be able to use SLF4J as alternative logging API. All that is necessary to make that work is a proper SLF4J adapter implementation. However, right now Glowstone includes the SLF4J implementation for Log4j 1.x, which isn't used in Glowstone at all. Include the correct SLF4J implementation for the java.util.logging API to make SLF4J logging work correctly.

Upstream has released updates that appear to apply and compile correctly. This update has not been tested by PaperMC and as with ANY update, please do your own testing Bukkit Changes: 5662c2b SPIGOT-6642: Throw better message if plugin.yml is empty aa8e035 PaperMC#636: Add FurnaceStartSmeltEvent 52073b3 SPIGOT-6646: Issue with map palette ranges 5f772da PaperMC#640: Add new Causes for LightningStrikeEvent CraftBukkit Changes: 4e18704 PaperMC#874: Add FurnaceStartSmeltEvent ed2b91c SPIGOT-6649: Call BlockFadeEvent when Nylium fades to Netherrack b7e3ce0 PaperMC#890: Include yaw in player's spawn location aeb711d PaperMC#889: Fix CraftChest close() sound being replaced with open sound. ca0fe5b SPIGOT-5561: Warning in logs when changing a Mob Spawner to Air on chunk load 2f038f2 PaperMC#886: Add new Causes for LightningStrikeEvent Spigot Changes: 38e6c03d Rebuild patches

kashike self-requested a review September 21, 2017 16:50

kashike added the status: needs testing Issue needs verification. label Sep 21, 2017

kashike requested changes Sep 21, 2017

View reviewed changes

kashike self-assigned this Sep 21, 2017

kashike requested a review from zachbr September 21, 2017 18:36

stephan-gh mentioned this pull request Sep 22, 2017

Use Log4j, add console improvements and allow plugins to use SLF4 for logging PaperMC/Waterfall#176

Merged

zachbr approved these changes Sep 23, 2017

View reviewed changes

stephan-gh added 4 commits September 23, 2017 21:30

Handle plugin prefixes in Log4j configuration

bbfc0c8

kashike approved these changes Sep 23, 2017

View reviewed changes

kashike merged commit e5e5063 into PaperMC:master Sep 23, 2017

stephan-gh deleted the slf4j branch September 23, 2017 19:57

mikroskeem added a commit to OrionMinecraft/Helios that referenced this pull request Sep 23, 2017

Update import, update libs and remove unneeded lib

9a314b1

SLF4J-over-Log4j2 is not needed anymore as of PaperMC/Paper#890

stephan-gh mentioned this pull request Sep 28, 2017

Ensure LOGGER is not equal to plugin logger before setting parent EssentialsX/Essentials#1570

Merged

stephan-gh mentioned this pull request Jan 28, 2018

Fix SLF4J logging for plugins GlowstoneMC/Glowstone#825

Merged

Machine-Maker mentioned this pull request Jul 17, 2021

Updated Upstream (Bukkit/CraftBukkit/Spigot) #6209

Merged

Uh oh!

Allow plugins to use SLF4J for logging #890

Allow plugins to use SLF4J for logging #890

Uh oh!

Conversation

stephan-gh commented Sep 21, 2017

Uh oh!

kashike Sep 21, 2017

Choose a reason for hiding this comment

Uh oh!

kashike Sep 21, 2017

Choose a reason for hiding this comment

Uh oh!

kashike Sep 21, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

kashike Sep 21, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

kashike Sep 21, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

kashike Sep 21, 2017

Choose a reason for hiding this comment

Uh oh!

kashike commented Sep 21, 2017

Uh oh!

stephan-gh commented Sep 21, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

kashike Sep 21, 2017

Choose a reason for hiding this comment

Uh oh!

stephan-gh commented Sep 21, 2017

Uh oh!

stephan-gh commented Sep 21, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

stephan-gh commented Sep 22, 2017

Uh oh!

kashike commented Sep 22, 2017

Uh oh!

stephan-gh commented Sep 22, 2017

Uh oh!

stephan-gh commented Sep 22, 2017

Uh oh!

stephan-gh commented Sep 22, 2017

Uh oh!

stephan-gh commented Sep 22, 2017

Uh oh!

kashike commented Sep 23, 2017

Uh oh!

kashike commented Sep 23, 2017

Uh oh!

mibby commented Sep 26, 2017

Uh oh!

stephan-gh commented Sep 26, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

kashike Sep 21, 2017 •

edited

Loading

kashike Sep 21, 2017 •

edited

Loading

kashike Sep 21, 2017 •

edited

Loading

stephan-gh commented Sep 21, 2017 •

edited

Loading

stephan-gh commented Sep 21, 2017 •

edited

Loading

stephan-gh commented Sep 26, 2017 •

edited

Loading