Double logging

[CC007]

In addition, Spring injects extraneous logging. Some log entries from (other) plugins are duplicated in the log, once with preceding > marker -- as though they were commands -- then without. Examples:

>[01:27:47] [Server thread/INFO]: [ServerListPlus] [Core] ServerListPlus profile is enabled!
[01:27:47] [Server thread/INFO]: [ServerListPlus] [Core] ServerListPlus profile is enabled!
>[01:28:04] [Server thread/INFO]: CONSOLE issued server command: /essentials:weather world_yellowdog storm 111
[01:28:04] [Server thread/INFO]: CONSOLE issued server command: /essentials:weather world_yellowdog storm 111

Originally posted by @SlimeDog in https://github.com/CC007/HeadsPluginAPI/issues/1#issuecomment-653888100

[CC007]

@SlimeDog Can you please provide a list of plugins that you are using?

This is a problem that was encountered during the development phase that was supposed to be fixed.

This only happens in Spigot, not in PaperMC, because of how the logging configuration is setup in Spigot.

[SlimeDog]

My test servers have 150+ plugins. The issue needs to be addressed globally. Some examples are shown above: EssentialsX and ServerListPlus. (If you really need the list, I will send PM.)

An UPDATE to the description: The extraneous lines are sent only to the console; they are not logged (f I look at a saved log file, they do not exist).

Similarly, "illegal" command notifications are also sent to the console (but not logged). For example, send to the console

> ======

With HeadsPluginAPI installed, the console reports

> ======
[09:17:25] [Server thread/INFO]: Unknown command. Type "/help" for help.

and the log reports

[09:17:25] [Server thread/INFO]: Unknown command. Type "/help" for help.

Without HeadsPluginAPI installed, the console reports

> ======

and the log reports nothing. We use this "feature" to advantage.

[SlimeDog]

Are these warnings related?

[07:42:29] [Server thread/WARN]: SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
[07:42:29] [Server thread/WARN]: SLF4J: Defaulting to no-operation (NOP) logger implementation
[07:42:29] [Server thread/WARN]: SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.

[CC007]

Yes, that might have something to do with it, not as the cause, but as a hint where to look.

[CC007]

@SlimeDog Can you please attach the logfile to this issue? That way I can look through the log to more easily find out where and why the double logging started.

[SlimeDog]

I can, but please confirm that you want it, as I am not currently running HeadsPluginAPI. Those WARN messages occurred without HeadsPluginAPI running, so may or may not be relevant.

Also, as noted above, the log does not contain the extraneous entries. Only the console output does.

[CC007]

I would preferably get the log of when HeadsPluginAPI was used (from when you reported the issue).

I know what those warn messages mean and that isn't necessarily a problem. It just means that a certain logging facade isn't properly configured (a dependency is missing), by the offending plugin, causing that plugin not to log certain things.

What it does signal that some other plugin might interact with the logging framework of Spigot in a way that my plugin doesn't understand, which bypasses a fix that I had to make in my plugin regarding logging.

That is why getting the log of your server would be quite useful, preferably from when my plugin was installed.

[SlimeDog]

..., preferably from when my plugin was installed.

That was understood. :)

You may find the log here. Please advise when you have copied it, so that I may delete from the server.

As noted above, this does not include the extraneous console entries. If you need to see those, I may be able to capture them separately.

[CC007]

@SlimeDog got it thanks. And from what point does the console logger start logging messages twice?

[SlimeDog]

By the way, there is no need to tag someone who is following an issue closely. I am subscribed.

[SlimeDog]

It will take extended effort to capture a readable console output, due to the way console posting works (lots of control characters). But one can see the duplicate-posting clearly on the console. Have you been able to replicate this behavior?

[SlimeDog]

These issues continue in HeadsPluginAPI 2.0.5.

[CC007]

Tip: since the logfile doesn't log twice, you can use the command tail -f <filename> to see the log as a workaround, until I've fixed this issue.

[SlimeDog]

Yeah. One of the many workarounds I employ. :)

[CC007]

Another workaround is to disable the SysOut appender:

1. open your spigot jar in WinRAR, 7-zip or an equivalent linux program.
2. open the log4j2.xml file into your favorite text/xml editor
3. remove or comment out the following lines:

<Console name="SysOut" target="SYSTEM_OUT">
    <PatternLayout pattern="[%d{HH:mm:ss}] [%t/%level]: %msg%n" />
</Console>

4. Save the file
5. run spigot

Now you shouldn't see any double log lines.

Using this workaround, you should be able to use spigot like you normally would.

PaperMC also doesn't include this log appender. I don't know why it is there. It might have something to do with compatibility when running on windows, but I never noticed it doing anything.

Meanwhile, I'm working on finding out which plugin is responsible for breaking my double logging fix.

[CC007]

I have posted a thread on spigot asking more information regarding the existance of 2 console appenders (which is what is causing your issue), because I have no idea why there are 2 appenders and why usually only one of them logs to console.

I also have been adding the plugins from your log one by one, to see if I can reproduce the issue. I have now added all plugins upto line 76 from the log you send me, but still no luck in reproducing the bug.

[SlimeDog]

grep -r log4j plugins/returns

Binary file plugins/WorldEdit-bukkit-7.2.0-b5186.jar matches
Binary file plugins/PhantomX-3.0.4.jar matches

if that's any help.

[CC007]

Thanks, I'll check if those cause any issues.

[CC007]

World Edit is not the cause. I have noticed that NetworkInterceptor logs one log line twice (once with the >), but that happens between enabling the plugin and finishing startup of the spring context, so that makes sense, because the class that should fix the issue has to be loaded first.

[01:57:17] [Server thread/INFO]: [NBTAPI] Success! This version of NBT-API is compatible with your server.
[01:57:17] [Server thread/INFO]: [McEventCore] Enabling McEventCore v0.1.0
[01:57:17] [Server thread/INFO]: [HeadsPluginAPI] Enabling HeadsPluginAPI v2.0.6
>[01:57:20] [Server thread/INFO]: [NetworkInterceptor] Intercepted outgoing connection to host 'DESKTOP-B5GAUBS'
[01:57:20] [Server thread/INFO]: [NetworkInterceptor] Intercepted outgoing connection to host 'DESKTOP-B5GAUBS'
[01:57:20] [Server thread/INFO]:
 _    _                   _        _____   _                _                    _____  _____
| |  | |                 | |      |  __ \ | |              (_)            /\    |  __ \|_   _|
| |__| |  ___   __ _   __| | ___  | |__) || | _   _   __ _  _  _ __      /  \   | |__) | | |
|  __  | / _ \ / _` | / _` |/ __| |  ___/ | || | | | / _` || || '_ \    / /\ \  |  ___/  | |
| |  | ||  __/| (_| || (_| |\__ \ | |     | || |_| || (_| || || | | |  / ____ \ | |     _| |_
|_|  |_| \___| \__,_| \__,_||___/ |_|     |_| \__,_| \__, ||_||_| |_| /_/    \_\|_|    |_____|
 _________________________________________________    __/ |  ________________________________
|_________________________________________________|  |___/  |________________________________|

 :: HeadsPluginAPI - version 2.0.6 ::

[01:57:20] [Server thread/INFO]: No active profile set, falling back to default profiles: default
[01:57:20] [Server thread/INFO]: Bootstrapping Spring Data JPA repositories in DEFAULT mode.
[01:57:20] [Server thread/INFO]: Finished Spring Data repository scanning in 106ms. Found 5 JPA repository interfaces.
[01:57:21] [Server thread/INFO]: BeanFactory id=79df52fe-af5d-3f5c-a4e5-53cd0137865c
[01:57:21] [Server thread/INFO]: HHH000204: Processing PersistenceUnitInfo [name: default]

[CC007]

Have you been able to get a console dump ready yet? I'm curious where console starts logging twice.

[SlimeDog]

I wasn't clear that you still wanted it. I'll try to generate a readable console, now.

[SlimeDog]

I can see why you're not finding anything. It looks like HeadsPluginAPI 2.0.5 does not double-write to the console. Was there a change that makes that explicable?

UPDATE: Same for 2.0.6.

(There are other issues, but not this one any longer, apparently.)

[CC007]

I updated the mcspring-boot dependency. Maybe something changed there that might have fixed it.

There should be a warning with a stacktrace now that you didn't see before, because it was logged at debug level by mcspring-boot before.

I'll close this issue for now. If it ever happens again, please inform me so I can try to find the root of the issues.

[SlimeDog]

Thank you for all your work on this.