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.
- 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
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