apache / apache/maven-surefire

[SUREFIRE-1818] Surefire buffers log messages in memory instead of printing them out to the terminal which leads to OOM error.

Open
#3,030 2 comments 0 reactions 0 assignees View on GitHub
bug priority:major
Dominant language
Java
Stars
461
Forks
588
Avg merge
1d 8h
Merged PRs (30d)
19

Description

**[Anton Ermolenko](https://issues.apache.org/jira/secure/ViewProfile.jspa?name=aermolenko)** opened **[SUREFIRE-1818](https://issues.apache.org/jira/browse/SUREFIRE-1818?redirect=false)** and commented

For unknown reason when running tests Surefire version 2.22.1 buffers logging messages in memory in `ConcurrentLinkedQueue` which leads to OutOfMemoryError when amount of logging messages is sufficiently large. If amount of memory is big enough to hold those messages, Surefire will print those log messages after running the tests.

Downgrading to 2.18.1 resolves the issue and log messages appear on the terminal without delay.

While it's printing those messages the following stack trace can be observed:

```java
"main" #1 prio=5 os_prio=0 tid=0x00007f3ff400b000 nid=0x30adf runnable [0x00007f3ffb3d7000]
java.lang.Thread.State: RUNNABLE
at java.io.FileOutputStream.writeBytes(Native Method)
at java.io.FileOutputStream.write(FileOutputStream.java:326)
at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)
at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140)
- locked <0x00000005cc251490> (a java.io.BufferedOutputStream)
at java.io.PrintStream.write(PrintStream.java:482)
- locked <0x00000005cc251470> (a java.io.PrintStream)
at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221)
at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:291)
at sun.nio.cs.StreamEncoder.flushBuffer(StreamEncoder.java:104)
- locked <0x00000005cc2515b0> (a java.io.OutputStreamWriter)
at java.io.OutputStreamWriter.flushBuffer(OutputStreamWriter.java:185)
at java.io.PrintStream.write(PrintStream.java:527)
- locked <0x00000005cc251470> (a java.io.PrintStream)
at java.io.PrintStream.print(PrintStream.java:583)
at org.fusesource.jansi.FilterPrintStream.write(FilterPrintStream.java:99)
at org.fusesource.jansi.FilterPrintStream.write(FilterPrintStream.java:107)
at org.fusesource.jansi.FilterPrintStream.print(FilterPrintStream.java:156)
at org.fusesource.jansi.FilterPrintStream.println(FilterPrintStream.java:231)
- locked <0x00000005cc22b6d0> (a org.fusesource.jansi.AnsiConsole$2)
at org.slf4j.impl.SimpleLogger.write(SimpleLogger.java:318)
at org.slf4j.impl.SimpleLogger.log(SimpleLogger.java:295)
at org.slf4j.impl.SimpleLogger.warn(SimpleLogger.java:522)
at org.apache.maven.cli.logging.Slf4jLogger.warn(Slf4jLogger.java:74)
at org.apache.maven.plugin.surefire.log.PluginConsoleLogger.warning(PluginConsoleLogger.java:92)
at org.apache.maven.plugin.surefire.booterclient.ForkStarter$CloseableCloser.run(ForkStarter.java:203)
at org.apache.maven.surefire.shade.org.apache.maven.shared.utils.cli.CommandLineUtils$1.call(CommandLineUtils.java:282)
at org.apache.maven.plugin.surefire.booterclient.ForkStarter.fork(ForkStarter.java:614)
at org.apache.maven.plugin.surefire.booterclient.ForkStarter.run(ForkStarter.java:282)
at org.apache.maven.plugin.surefire.booterclient.ForkStarter.run(ForkStarter.java:245)
at org.apache.maven.plugin.surefire.AbstractSurefireMojo.executeProvider(AbstractSurefireMojo.java:1183)
at org.apache.maven.plugin.surefire.AbstractSurefireMojo.executeAfterPreconditionsChecked(AbstractSurefireMojo.java:1011)
at org.apache.maven.plugin.surefire.AbstractSurefireMojo.execute(AbstractSurefireMojo.java:857)
at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo(DefaultBuildPluginManager.java:137)
at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:208)
at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:154)
at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:146)
at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:117)
at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:81)
at org.apache.maven.lifecycle.internal.builder.singlethreaded.SingleThreadedBuilder.build(SingleThreadedBuilder.java:56)
at org.apache.maven.lifecycle.internal.LifecycleStarter.execute(LifecycleStarter.java:128)
at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:305)
at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:192)
at org.apache.maven.DefaultMaven.execute(DefaultMaven.java:105)
at org.apache.maven.cli.MavenCli.execute(MavenCli.java:954)
at org.apache.maven.cli.MavenCli.doMain(MavenCli.java:288)
at org.apache.maven.cli.MavenCli.main(MavenCli.java:192)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.codehaus.plexus.classworlds.launcher.Launcher.launchEnhanced(Launcher.java:289)
at org.codehaus.plexus.classworlds.launcher.Launcher.launch(Launcher.java:229)
at org.codehaus.plexus.classworlds.launcher.Launcher.mainWithExitCode(Launcher.java:415)
at org.codehaus.plexus.classworlds.launcher.Launcher.main(Launcher.java:356)

```

Dominator tree of produced heap dump:

!image-2020-07-11-18-57-41-164.png|width=581,height=86!

 

Heap dump can be downloaded [here](https://drive.google.com/file/d/1LL2ZRmUmIb708HUFC1wNfeRDMOtIwKWz/view?usp=sharing)

---

**Affects:** 2.22.1

**Attachments:**
- [image-2020-07-11-18-57-41-164.png](https://issues.apache.org/jira/secure/attachment/13007467/image-2020-07-11-18-57-41-164.png) (_43.28 kB_)

1 votes, 4 watchers

Contributor guide

Open the contributing guide

Research direction

Start by tracing the mentioned ForkStarter$CloseableCloser path and the ConcurrentLinkedQueue that buffers logging messages. Reproduce the issue with a sufficiently large logging workload and inspect the relevant Surefire output behavior. Done means log messages appear without waiting for test completion and the queue no longer causes unbounded memory use.

Written by the indexing model from the issue text.

Assessment

Tech stack
java
Domain
build-system, testing
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Needs clarification
Newbie friendliness
30/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.