Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add System.out.println catcher #6278

Merged
merged 1 commit into from
Aug 2, 2021

Conversation

underscore11code
Copy link
Member

Inspired by @Draycia's SysoutCatcher (Used with permission). Redirects any plugin calls to System.out/err.print(ln) to the plugin's logger, along with a nag message (per-plugin disableable with a system property).

There's probably a ton of problems y'all gonna have with this, among which I anticipate being the class finder, nag message, etc etc. If you want, I'm on the Discord, @_11#0011, feel free to ping me to discuss there instead.

@underscore11code underscore11code requested review from a team as code owners July 27, 2021 02:47
@Machine-Maker
Copy link
Member

For finding the plugin class that called it, would using log4j's StackLocaterUtil be better than writing your own? I believe it does the same thing and is used by log4j in its LogManager#getLogger() for getting a logger for the caller class.

@underscore11code
Copy link
Member Author

If you're referring to this over StackTraceElement element = Thread.currentThread().getStackTrace()[2]; /* snip */ element.getClassName(), the javadoc comment is the following:

Consider this class private. Provides various methods to determine the caller class.

To me, that implies that they treat it as internal code and thus won't worry about API breakage.

If you're referring to the tryFindClass method, that's a result of classloaders. Simple Class.forNames weren't working, so I have to do that loop to find the plugin's classloader.

@underscore11code
Copy link
Member Author

underscore11code commented Jul 27, 2021

Ignore, apparently my shit internet made it comment twice.

@electronicboy
Copy link
Member

electronicboy commented Jul 27, 2021

https://docs.oracle.com/javase/9/docs/api/java/lang/StackWalker.html#getCallerClass--

No idea how this works with our setup though, but, worth looking at

@underscore11code
Copy link
Member Author

Yeah looks like StackWalker works, and is much tidier. I was expecting classloader issues, but looks like it's fine. Refactored to use it.

@A248
Copy link
Contributor

A248 commented Jul 28, 2021

Perhaps you should also move the calls to setOut and setErr to the same place where this happens:

        System.setOut(IoBuilder.forLogger(logger).setLevel(Level.INFO).buildPrintStream());
        System.setErr(IoBuilder.forLogger(logger).setLevel(Level.WARN).buildPrintStream());

That would make it clearer which calls happen first

patches/server/0731-Add-System.out.println-catcher.patch Outdated Show resolved Hide resolved
@underscore11code underscore11code force-pushed the feature/sysoutcatcher branch 2 times, most recently from 806b54e to a935a42 Compare July 29, 2021 00:23
@underscore11code
Copy link
Member Author

Rebased on latest. Switched prefixes as @kashike requested. Switched to full class names as @A248 requested.

patches/server/0731-Add-System.out.println-catcher.patch Outdated Show resolved Hide resolved
patches/server/0731-Add-System.out.println-catcher.patch Outdated Show resolved Hide resolved
+ } else blacklistedPlugins = ImmutableSet.of();
+
+ // Listen to System.out.println
+ PrintStream wrappedOut = new PrintStream(System.out) {
Copy link
Contributor

@Proximyst Proximyst Jul 29, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

(Blocker) I'd prefer if these anonymous classes were replaced with a private class and use variables for the different constants used.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

All right, I've done what I assume you meant, lmk how this looks.

@underscore11code underscore11code force-pushed the feature/sysoutcatcher branch 2 times, most recently from 1a880bc to ab31b14 Compare July 29, 2021 05:32
@LlmDl
Copy link

LlmDl commented Jul 29, 2021

Seeing as how there's already a plugin that does this, when the admin wants it, I don't see this as a necessary thing.

Just my two cents: some plugin creators like to use sysout's for cleaner looking logs, but the logs themselves end up being different based on what server software is being used.

@electronicboy
Copy link
Member

electronicboy commented Jul 29, 2021

not using your own logger is a pretty common anti-practice which often creates a huge number of headaches for server admins due to plugin devs failing to use their own loggers, it makes it hard to work out where something is coming from and there is generally very little sane reason to do so

long term intent is that all plugin logger usage should be directed to the correct place to limit the side-effects of this anti-practice which just poses many headaches for server owners and us

@underscore11code
Copy link
Member Author

Seeing as how there's already a plugin that does this, when the admin wants it, I don't see this as a necessary thing.

From the original PR note:

Inspired by @Draycia's SysoutCatcher (Used with permission).

Copy link
Member

@jpenilla jpenilla left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Honestly I would prefer the system property to be for disabling the nag outright rather than a whitelist. Being a system property, it's already pretty out of sight for the "average server owner" (compared to as if it were a config option or similar).

@theminecoder
Copy link
Contributor

Honestly I would prefer the system property to be for disabling the nag outright rather than a whitelist. Being a system property, it's already pretty out of sight for the "average server owner" (compared to as if it were a config option or similar).

Yeh this needs a global opt out for even adding the prefixes. Networks built on entirely custom plugins often know what they are doing and don't want extra things like [SYSOUT] filling up their logging.

@Draycia
Copy link

Draycia commented Jul 30, 2021

Yeh this needs a global opt out for even adding the prefixes. Networks built on entirely custom plugins often know what they are doing and don't want extra things like [SYSOUT] filling up their logging.

This only effects people using sysout, if you use a logger to begin with you won't have any issue. Logger instances are simple to obtain and there are no shortage of ways to get them.

Edit:
If you really want the anonymous logging, Bukkit.getLogger() remains untouched and anonymous.

@A248
Copy link
Contributor

A248 commented Jul 30, 2021

I don't see a reason to deny the request for an on/off system property to toggle this behavior. Personally I'm indifferent, since I will always have this behavior enabled.

If you really want the anonymous logging, Bukkit.getLogger() remains untouched and anonymous.

No, don't do that. That would be swapping a bad practice for a slightly less bad one, at which point you've accomplished little.

@underscore11code
Copy link
Member Author

Yeah I'll swap it over to a boolean on/off when I get home. Don't actually remember my rationale for per-plugin whitelist vs blanket disable of nag.

One thing I'm noticing is due to me overriding the println(String) method instead of println(Object), Throwable#printStackTrace is not touched. Is this something I should be investigating logging too?

@A248
Copy link
Contributor

A248 commented Jul 31, 2021

No, don't mess with that. Would you want to see a stacktrace interspersed with nag messages? In this ecosystem, be glad for a plugin to use printStackTrace rather than swallow the exception whole.

@underscore11code
Copy link
Member Author

Oops sorry, should have clarified. For exceptions, I'd disable the nags. Because yeah I agree, printStackTrace is perfectly fine and should be used by all means where appropriate.

Thinking about it though, it'd probably be too hard to find the calling class of that though, so I'd need to also loose the prefix for exception methods, but that should be fine, should be able to figure out the cause of an exception from the stacktrace.

@Proximyst
Copy link
Contributor

The global switch to disable nags is a good idea. Personally, I wouldn’t mind #println(Object) also doing this as slf4j and log4j APIs make it easy to log meaningful text for this.

There should not be an option to disable the extra prefix, however. It’s a tiny bit of noise, and if these custom networks don’t want it, I suggest just moving to local constants for per-class loggers, which is very clean, very easy, and a small price to pay for cleaner logs.

@Proximyst Proximyst dismissed stale reviews from jpenilla and kashike August 2, 2021 07:03

Fixing

@mcmonkey4eva
Copy link

So, when a plugin embeds an external library, and that library outputs to System.out or System.err, what should the plugin author do about that?
(Assume it would be unreasonably painful to try to maintain a fork of that external lib just to change the log method used)

Because, yknow, the output telling server owners to nag me about something I don't control isn't particularly helpful. I strongly imagine I'm not going to be the only plugin author to ever embed an external library, and thus not the only person that needs a way to disable the spam.
(If it is just me, I can always just hackaround it a lil, but I'm posting specifically because I think it's going to be a lot more than just me)

@kezz
Copy link
Contributor

kezz commented Aug 4, 2021

Just out of curiosity, what libraries are you using that aren't using even the most basic of logging frameworks?

@electronicboy
Copy link
Member

The fact that the nag message shows more than once is defo something which should be changed, but, these libraries really should be using a logger, not doing so especially in these types of environments is generally deemed as something we got past over using a proper logging framework

I don't think that there is an ultra great solution here otherwise but using Sout has been a long standing issue which causes many issues for server owners, which, er...

@mcmonkey4eva
Copy link

Re: a solution: At the very least, something that can be set or called somewhere within a plugin to indicate it should be excluded from the nag method. A sort of "I understand it's wrong but can't change it" checkbox (note: specifically set by the plugin, not by each and every server owner).

Also re: aren't using even the most basic of logging frameworks? most logging frameworks are just overcomplicated ways of calling System.out with some formatting and all added. In other words: an external library that has a logging framework is still caught by this nag message.

@kezz
Copy link
Contributor

kezz commented Aug 4, 2021

Can you tell us what library is causing this issue? Logging frameworks are far more than just sysout wrappers and I find it highly surprising that a library is using a logging framework that doesn't support one of the standard APIs supported by Paper et al.

@mcmonkey4eva
Copy link

Again, as I said: I can hackaround for my own single case (and in fact already have), I'm posting here because I genuinely believe this is not going to be just my one case.

@MiniDigger
Copy link
Member

people will nag the author, who can see that this isn't actually caused by the plugins code but a 3rd party, and thus can forward the issue to the author of said library. no production code should use system out.

@Phoenix616
Copy link
Contributor

HikariCP uses slf4j and still triggers this warning so just using a logging framework definitely doesn't solve this for all libraries...

@kezz
Copy link
Contributor

kezz commented Aug 6, 2021

Well you should bring this up with them https://github.com/brettwooldridge/HikariCP/search?q=out.println

@Phoenix616
Copy link
Contributor

Phoenix616 commented Aug 6, 2021

Well you should bring this up with them https://github.com/brettwooldridge/HikariCP/search?q=out.println

These are not the log messages I am talking about, any of their slf4j logging usage will go to System out as Paper does not seem to properly support that framework. ([STDERR] SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".)

@Proximyst
Copy link
Contributor

@Phoenix616 Can't reproduce that.

[14:30:10 INFO]: [com.zaxxer.hikari.HikariDataSource] HikariPool-1 - Starting...
[14:30:11 INFO]: [com.zaxxer.hikari.pool.HikariPool] HikariPool-1 - Added connection conn0: url=jdbc:h2:mem:testplugin user=
[14:30:11 INFO]: [com.zaxxer.hikari.HikariDataSource] HikariPool-1 - Start completed.

...

> sql query SELECT 2;
[14:30:21 INFO]: [st.proximy.papertest.command.SqlCommand] Executed query; got: HikariProxyResultSet@615535710 wrapping rs0: org.h2.result.LocalResultImpl@9b126 columns: 1 rows: 1 pos: -1
> version
[14:30:43 INFO]: Checking version, please wait...
[14:30:43 INFO]: This server is running Paper version git-Paper-157 (MC: 1.17.1) (Implementing API version 1.17.1-R0.1-SNAPSHOT) (Git: f521a18)
You are running the latest version
Previous version: git-Paper-"f521a18" (MC: 1.17.1)
> sysout helo
[14:31:47 INFO]: [Paper-Test-Plugin] [STDOUT] helo
[14:31:47 WARN]: Nag author(s): '[Proximyst]' of 'Paper-Test-Plugin' about their usage of System.out/err.print. Please use your plugin's logger instead (JavaPlugin#getLogger).

...

[14:32:24 INFO]: [Paper-Test-Plugin] Disabling Paper-Test-Plugin v0.0.0-SNAPSHOT+dev
[14:32:24 INFO]: [com.zaxxer.hikari.HikariDataSource] HikariPool-1 - Shutdown initiated...
[14:32:24 INFO]: [com.zaxxer.hikari.HikariDataSource] HikariPool-1 - Shutdown completed.
    implementation("com.zaxxer:HikariCP:5.0.0")
    implementation("com.h2database:h2:1.4.200")
    try {
      org.h2.Driver.load();
      final var hikariConfig = new HikariConfig();
      hikariConfig.setJdbcUrl("jdbc:h2:mem:testplugin");
      this.hikariDataSource = new HikariDataSource(hikariConfig);
    } catch (final Exception ex) {
      LOGGER.warn("Could not initialise Hikari with H2", ex);
    }

@Phoenix616
Copy link
Contributor

Interesting. Maybe h2 includes bindings? That's the only difference to my setup (and me using maven).

Manually including the slf4j-log4j-impl bindings artifact solved this for me though. Maybe it might be worth considering directly including that in Paper although I guess that could result in incompatibilities with different log4j implementation versions.

@Proximyst
Copy link
Contributor

Same result with:

    implementation("com.h2database:h2:1.4.200") {
        isTransitive = false
    }

HikariCP is the only one which brings in slf4j-api in my environment (see #6343 as to why not even Paper does). Perhaps this is a fix in 5.0.0 of HikariCP?

@Phoenix616
Copy link
Contributor

Turns out my issue stemmed from the fact that I relocated the org.slf4j package which made it so HikariCP didn't detect it anymore. The solution is to either not relocate it (if you are fine with conflicts), exclude it completely from the HikariCP dependency (if you are fine with it potentially breaking when the one included in Paper isn't compatible with the one HikariCP tries to use), or directly shade slf4j-log4j bindings and be able to relocate those.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet