Paper: Async Log4j-2 makes Thread Context related logging impossible (e.g. Sentry)

[janLindner]

What behaviour is expected:

When using thread related contexts the correct contexts are not visible on the logger.

Sentry.getContext().setUser(
    new UserBuilder()
        .setId(e.getUniqueId().toString())
        .setUsername(e.getName())
        .setIpAddress(e.getAddress().getHostAddress())
        .setData(
            ImmutableMap.<String, Object>builder()
                .put("profileComplete", e.getPlayerProfile().isComplete())
                .build()
        )
        .build()
);
Sentry.getContext().recordBreadcrumb(
    new BreadcrumbBuilder()
        .setTimestamp(new Date())
        .setCategory("login")
        .setLevel(Breadcrumb.Level.CRITICAL)
        .setMessage("User entered pre login event")
        .build()
);
Sentry.getContext().addExtra("playerProfile", e.getPlayerProfile());


.......


getSLF4JLogger().error(
    "An error occurred while waiting for the logout of the previous user session of user {} ({}).",
    e.getName(),
    e.getUniqueId(),
    ex
);

What behaviour is observed:

The logging is executed in a different thread context and therefore not taken into account when passing the log event to Sentry.

Steps/models to reproduce:

Use a thread context when logging something. (In the example we are using a manually added SentryAppender)

Paper build number:

paper-136

Anything else:

This behavior was probably introduced by this patch: Aync Logging Patch

The behavior is likely to be perfectly fine in most cases. It might be an idea to add a configuration or a flag to toggle this behavior.

[aikar]

I think you're the only person in the world to even run into a scenario to want to disable async logging lol.
I'm not sure we can even add a config for this due to it being a config file instead of code, as well as the fact logging is loaded so early.

You may be able to load this config file from your server root and revert the change but I don't know if there is a flag for that, but I'd assume so.

I would suggest looking into if you can change those 2 configs through code for your own logger instance only, but I'm not sure how to do that myself. Maybe some others know

[A248]

You can use the log4j2.contextSelector system property

[Scrayos]

I think you're the only person in the world to even run into a scenario to want to disable async logging lol.

We thought so too. :smile:

But sadly Sentry does by default only include two ContextManagers. One is a singleton manager, that is not suitable for any kind of asynchronous programming as prepared contexts could "leak" into other execution paths/logging statements. The other is the ThreadLocal implementation that sadly retrieves the context during message processing (as an appender to the log). So our best bet is to go back to synchronous logging for our logger at least.

I'm not sure we can even add a config for this due to it being a config file instead of code, as well as the fact logging is loaded so early.

We'll have a stab at it and see if we can somehow overwrite the ContextSelector (ideally just for our loggers). If that won't work, maybe a system property/cli flag would still be an option. And I would even prefer that over a config option as it is a very special case for sure. But with Sentry becoming more and more popular, this problem will maybe occur for more developers over time.

Edit: @A248 Ah, thank you. I'll try that! :+1:

[janLindner]

You can use the log4j2.contextSelector system property

We tried setting this property both via system property as well as environment variable but it was not acutally applied to the log configuration. When using the legacy system property Log4jContextSelector it worked.

But this is very confusing as paper is using log4j2 and the order of properties described by Configuring Log4j 2 is the other way arround.

[A248]

The reason for that being Paper uses Log4JContextSelector itself, so I am guessing that's why you need to override it and not the newer option.

https://github.com/PaperMC/Paper/blob/0dcce21fe6ff872c7242f7ca92c91b807b2fd073/Spigot-Server-Patches/0244-Use-asynchronous-Log4j-2-loggers.patch#L53

[Scrayos]

Yeah, we considered that as a reason for the outlined behaviour aswell, but it was quite surprising, that it didn't only ignore said property, but also all other environment-variables that we tried to set. We tried setting our configuration through the environment variable LOG4J_CONFIGURATION_FILE and also tried overriding the ContextSelector through LOG4J_CONTEXT_SELECTOR. Neither of those seemed to have any impact. As it works now, it's not really urgent to find out the reason for this, but it would still be nice to know why all environment variables didn't seem to have an impact.

Same thing btw. for setting log4j*2*.configurationFile instead of log4j.configurationFile as a system property. This also seemed to have no effect on the logging at all. So perhaps the version of Log4j2 used doesn't match the version of the documentation?

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[kashike]

Us setting Log4jContextSelector to org.apache.logging.log4j.core.async.AsyncLoggerContextSelector causes an issue with certain libraries (like Guice) - we might want to reconsider using the asynch selector if possible.

[A248]

To elaborate on that, Guice overrides Throwable#getMessage which can cause extra classloading. This can lead to difficult-to-debug (unless you've seen it before) situations:

1. Plugin using Guice starts up
2. Usage of Guice throws exception in plugin's onEnable
3. Plugin is disabled because its onEnable threw an exception. Bukkit logs exception which caused the plugin to fail. Plugin's PluginClassLoader is closed.
4. Log4j gets around to actually logging the exception, on its async logging thread.
5. Throwable#getMessage, which is overridden by Guice, causes further classloading.
6. Classloading fails because the PluginClassLoader was shut down.
7. Async logging thread encounters this classloading exception while logging. Original exception is lost but the mysterious exception on async logging thread hints at the problem.

[mdcfe]

Just to add to this: you can replicate the issue with Guice using this test plugin (download). This plugin creates an injector then deliberately triggers an exception from Guice, and leads to results such as this where the logging of the original exception fails and triggers another exception.