Memory leak in non-quarkus main() in quarkus-using module (due to quarkus dependencies)

[ge0ffrey]

To reproduce, take any quarkus quickstart and add this class in src/test/java (or src/main/java):

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class LoggingMemoryLeakMain {

    protected static final Logger logger = LoggerFactory.getLogger(LoggingMemoryLeakMain.class);

    public static void main(String[] args) {
        for (int i = 0; i < 1_000_000_000; i++) {
            System.out.println("Sout iteration " + i);
            if (i % 1_000_000 == 0) {
                logger.info("Iteration {}", i);
            } else if (i % 1_000 == 0) {
                logger.debug("Iteration {}", i);
            } else {
                logger.trace("Iteration {}", i);
            }
        }
    }

}

With JDK 11, I get this:

Sout iteration 21071313
Sout iteration 21071314

Exception: java.lang.OutOfMemoryError thrown from the UncaughtExceptionHandler in thread "main"

That takes a few minutes. Use -Xmx64m to get it in a few seconds.
Its caused by jboss logging that by default remembers all logging statements in memory, see https://quarkusio.zulipchat.com/#narrow/stream/187030-users/topic/Memory.20leak.2C.20logging.20and.20psvm

This memory leak might also affects unit tests that don't use quarkus integration.

Why is this a problem?
It's often useful to add plain old mains in a quarkus module too, without having to create yet another module for them. These do not replace the Quarkus main that is the actually application. Examples include:

• to run a benchmark
• to experiment with a new library before mixing Quarkus in the complexity mix
• to run a tool such as converting adoc into html that goes in META-INF/resources, etc.
• ...

All of these have alternative ways of accomplishing that goal, which are better but more work intensive: it's easier to temporary just add a plain-java main and it's very surprising that quarkus crippled that with a memory leak. It doesn't abide by the principle of least surprise.

[mkouba]

I can confirm the leak. The problem is that io.quarkus.bootstrap.logging.InitialConfigurator is used even for non-quarkus main (LoggingMemoryLeakMain) and the delayed handler stores all log records in an ArrayDeque but since it's never activated, no records are removed from the deque.

I think that we should detect a non-quarkus main and skip the handler registration in that case. CC @dmlloyd @gsmet

[dmlloyd]

I believe @geoand looked into this (detecting a non-Quarkus main) a while ago and concluded that there isn't currently a really good mechanism for doing that?

[mkouba]

I believe @geoand looked into this (detecting a non-Quarkus main) a while ago and concluded that there isn't currently a really good mechanism for doing that?

In that case, we could at least try to limit the size of the deque in the delayed handler?

[geoand]

I believe @geoand looked into this (detecting a non-Quarkus main) a while ago and concluded that there isn't currently a really good mechanism for doing that?

That is correct, I did three prototypes and none turned out to make any sense...

[dmlloyd]

To clarify the problem, the log configurator is installed independently of main (and likely before it ever starts) when the first log message is logged, with the intent of preventing log messages from being lost. The JDK gives no portable mechanism to determine what program was, or is about to be, started. The configurator has no access to this information, therefore it relies specifically on main to indicate when the configuration has been read, which cannot be done until after main is called due to command-line processing which in turn may affect the configuration (including logging configuration).

Putting a cap on the deque does not prevent the leak; it merely prevents the leak from crashing the program. We may need a pragmatic compromise, such as requiring the user to call a Quarkus.userMain() method from the top of main. This may also be useful for other scenarios where libraries are left in an intermediate state with the expectation of main to finish up any initialization.

[mkouba]

Putting a cap on the deque does not prevent the leak; it merely prevents the leak from crashing the program.

Sure it does not but if the limit is low enough (1000 records or so) the impact will be negligible for the user main and no log records should be lost for quarkus main.

We may need a pragmatic compromise, such as requiring the user to call a Quarkus.userMain() method from the top of main

That sounds reasonable but even if properly documented it's kind of unexpected. In other words, most users will never do that.

Therefore, I believe that we should apply both the limit and the Quarkus.userMain() call. @dmlloyd WDYT?

[dmlloyd]

I suppose the error reporter could report a queue overrun in that case so the user would know of the problem.

[mkouba]

Do you mean java.util.logging.Handler.getErrorManager()?

BTW reporting an error does not really help in this particular case where dozens of log messages are written to the standard output...

[dmlloyd]

I think in this case, nothing will have been logged because the user main never set up the handler for it. So either they would get a one-time error saying they've overrun the queue and should configure logging correctly, or else they would get the logs that they want because they configured it correctly.

[mkouba]

I think in this case, nothing will have been logged because the user main never set up the handler for it.

Well, it is logged, maybe because the SLF4J adapter is used and the class that declares the main is using SLF4J API...

[dmlloyd]

That should only happen if there's some broken dependency (for example if they have included multiple SLF4J backend JARs). Trying to use other logging frameworks from a Quarkus project classpath will not ever work.

[mkouba]

That should only happen if there's some broken dependency (for example if they have included multiple SLF4J backend JARs). Trying to use other logging frameworks from a Quarkus project classpath will not ever work.

I was able to reproduce the issue in three simple steps:

1. Generate a simple app via https://code.quarkus.io/?e=resteasy-reactive
2. Add the LoggingMemoryLeakMain mentioned in the issue description
3. Run the LoggingMemoryLeakMain#main() from the IDE (Eclipse in my case)

I don't see any other SLF4J backend in the dependency tree (only slf4j-jboss-logmanager).

[dmlloyd]

That should only happen if there's some broken dependency (for example if they have included multiple SLF4J backend JARs). Trying to use other logging frameworks from a Quarkus project classpath will not ever work.

I was able to reproduce the issue in three simple steps:

1. Generate a simple app via https://code.quarkus.io/?e=resteasy-reactive
2. Add the LoggingMemoryLeakMain mentioned in the issue description
3. Run the LoggingMemoryLeakMain#main() from the IDE (Eclipse in my case)

I don't see any other SLF4J backend in the dependency tree (only slf4j-jboss-logmanager).

What exactly is being logged?

[mkouba]

What exactly is being logged?

Oh, I'm sorry. I got confused... logger.info() does not log anything.