Error inside systemOut parser: java.lang.IllegalStateException: testSetStarting called twice

Details

Type: Bug
Status: Closed
Priority: Major
Resolution: Fixed
Affects Version/s: 2.6
Fix Version/s: 2.7
Component/s: Maven Surefire Plugin
Labels:
None
Environment:
Windows 7
java version "1.6.0_19"
Java(TM) SE Runtime Environment (build 1.6.0_19-b04)
Java HotSpot(TM) 64-Bit Server VM (build 16.2-b04, mixed mode)
Maven 2.2.1

Complexity:
Intermediate
Number of attachments :
0

Description

After upgrading surefire/surefire report from 2.5 to 2.6 it fails after test are run with
[INFO] ------------------------------------------------------------------------
[ERROR] BUILD ERROR
[INFO] ------------------------------------------------------------------------
[INFO] Error while executing forked tests.; nested exception is org.apache.maven.surefire.booter.shade.org.codehaus.plexus.util.cli.CommandLineException: Error
inside systemOut parser

testSetStarting called twice
[INFO] ------------------------------------------------------------------------
[DEBUG] Trace
org.apache.maven.lifecycle.LifecycleExecutionException: Error while executing forked tests.; nested exception is org.apache.maven.surefire.booter.shade.org.code
haus.plexus.util.cli.CommandLineException: Error inside systemOut parser
at org.apache.maven.lifecycle.DefaultLifecycleExecutor.executeGoals(DefaultLifecycleExecutor.java:719)
at org.apache.maven.lifecycle.DefaultLifecycleExecutor.executeGoalWithLifecycle(DefaultLifecycleExecutor.java:556)
at org.apache.maven.lifecycle.DefaultLifecycleExecutor.executeGoal(DefaultLifecycleExecutor.java:535)
at org.apache.maven.lifecycle.DefaultLifecycleExecutor.executeGoalAndHandleFailures(DefaultLifecycleExecutor.java:387)
at org.apache.maven.lifecycle.DefaultLifecycleExecutor.executeTaskSegments(DefaultLifecycleExecutor.java:348)
at org.apache.maven.lifecycle.DefaultLifecycleExecutor.execute(DefaultLifecycleExecutor.java:180)
at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:328)
at org.apache.maven.DefaultMaven.execute(DefaultMaven.java:138)
at org.apache.maven.cli.MavenCli.main(MavenCli.java:362)
at org.apache.maven.cli.compat.CompatibleMain.main(CompatibleMain.java:60)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.codehaus.classworlds.Launcher.launchEnhanced(Launcher.java:315)
at org.codehaus.classworlds.Launcher.launch(Launcher.java:255)
at org.codehaus.classworlds.Launcher.mainWithExitCode(Launcher.java:430)
at org.codehaus.classworlds.Launcher.main(Launcher.java:375)
Caused by: org.apache.maven.plugin.MojoExecutionException: Error while executing forked tests.; nested exception is org.apache.maven.surefire.booter.shade.org.c
odehaus.plexus.util.cli.CommandLineException: Error inside systemOut parser
at org.apache.maven.plugin.surefire.SurefirePlugin.execute(SurefirePlugin.java:579)
at org.apache.maven.plugin.DefaultPluginManager.executeMojo(DefaultPluginManager.java:490)
at org.apache.maven.lifecycle.DefaultLifecycleExecutor.executeGoals(DefaultLifecycleExecutor.java:694)
... 17 more
Caused by: org.apache.maven.surefire.booter.SurefireBooterForkException: Error while executing forked tests.; nested exception is org.apache.maven.surefire.boot
er.shade.org.codehaus.plexus.util.cli.CommandLineException: Error inside systemOut parser
at org.apache.maven.surefire.booter.SurefireBooter.fork(SurefireBooter.java:685)
at org.apache.maven.surefire.booter.SurefireBooter.forkSuites(SurefireBooter.java:485)
at org.apache.maven.surefire.booter.SurefireBooter.runSuitesForkOnce(SurefireBooter.java:385)
at org.apache.maven.surefire.booter.SurefireBooter.run(SurefireBooter.java:246)
at org.apache.maven.plugin.surefire.SurefirePlugin.execute(SurefirePlugin.java:575)
... 19 more
Caused by: org.apache.maven.surefire.booter.shade.org.codehaus.plexus.util.cli.CommandLineException: Error inside systemOut parser
at org.apache.maven.surefire.booter.shade.org.codehaus.plexus.util.cli.CommandLineUtils.executeCommandLine(CommandLineUtils.java:222)
at org.apache.maven.surefire.booter.shade.org.codehaus.plexus.util.cli.CommandLineUtils.executeCommandLine(CommandLineUtils.java:114)
at org.apache.maven.surefire.booter.SurefireBooter.fork(SurefireBooter.java:681)
... 23 more
Caused by: java.lang.IllegalStateException: testSetStarting called twice
at org.apache.maven.surefire.booter.output.FileOutputConsumerProxy.testSetStarting(FileOutputConsumerProxy.java:112)
at org.apache.maven.surefire.booter.output.ForkingStreamConsumer.consumeLine(ForkingStreamConsumer.java:60)
at org.apache.maven.surefire.booter.shade.org.codehaus.plexus.util.cli.StreamPumper.consumeLine(StreamPumper.java:197)
at org.apache.maven.surefire.booter.shade.org.codehaus.plexus.util.cli.StreamPumper.run(StreamPumper.java:137)

Issue Links

relates to

SUREFIRE-640 org.apache.maven.surefire.booter.shade.org.codehaus.plexus.util.cli.CommandLineException: Error inside systemErr parser

Activity

Ascending order - Click to sort in descending order

Hide

Permalink

Michael Hinterseher added a comment - 18/Aug/10 10:59 AM

The error occurs only when <redirectTestOutputToFile>true</redirectTestOutputToFile> is configured.

Show

Michael Hinterseher added a comment - 18/Aug/10 10:59 AM The error occurs only when <redirectTestOutputToFile>true</redirectTestOutputToFile> is configured.

Hide

Permalink

Kristian Rosenvold added a comment - 18/Aug/10 1:25 PM

Thank you for reporting this issue. I am unable to reproduce it, so there is obviously some other part of your configuration that I am missing. If you can assist with the following:

svn co https://svn.apache.org/repos/asf/maven/surefire/trunk/surefire-integration-tests/src/test/resources/surefire-639-redirectTestOutputToFileWhenForking
cd surefire-639-redirectTestOutputToFileWhenForking

mvn -Dsurefire.version=2.6 -DforkMode=once -Dredirect.to.file=false test

You can try adjusting various parameters, and also maybe try to find out which modifications to the pom.xml in this project that is required to reproduce the problem.

Show

Kristian Rosenvold added a comment - 18/Aug/10 1:25 PM Thank you for reporting this issue. I am unable to reproduce it, so there is obviously some other part of your configuration that I am missing. If you can assist with the following: svn co https://svn.apache.org/repos/asf/maven/surefire/trunk/surefire-integration-tests/src/test/resources/surefire-639-redirectTestOutputToFileWhenForking cd surefire-639-redirectTestOutputToFileWhenForking mvn -Dsurefire.version=2.6 -DforkMode=once -Dredirect.to.file=false test You can try adjusting various parameters, and also maybe try to find out which modifications to the pom.xml in this project that is required to reproduce the problem.

Hide

Permalink

Kristian Rosenvold added a comment - 18/Aug/10 1:36 PM

You might want to try with the actual provider (junit/testng) and the versions you're using.

Show

Kristian Rosenvold added a comment - 18/Aug/10 1:36 PM You might want to try with the actual provider (junit/testng) and the versions you're using.

Hide

Permalink

Michael Hinterseher added a comment - 19/Aug/10 4:29 AM - edited

I found the problem.
In case the last System.out doesn't force a line break the test results get appended on the end of the previous System.out.
This causes an error during reading the results but only in case of redirect to file is on
To reproduce just change in Test2 "println" to "print" like following:
@AfterClass
public static void testWithFailingAssumption3()

{ System.out.print( "After628Test2 on" + Thread.currentThread().getName()); }

Show

Michael Hinterseher added a comment - 19/Aug/10 4:29 AM - edited I found the problem. In case the last System.out doesn't force a line break the test results get appended on the end of the previous System.out. This causes an error during reading the results but only in case of redirect to file is on To reproduce just change in Test2 "println" to "print" like following: @AfterClass public static void testWithFailingAssumption3() { System.out.print( "After628Test2 on" + Thread.currentThread().getName()); }

Hide

Permalink

Kristian Rosenvold added a comment - 03/Nov/10 2:59 PM

There is a decent chance this issue was fixed by the fix for ~~SUREFIRE-640~~. I am still not able to reproduce this, even if I change the System.out.println as you suggest. Please re-test with 2.7-SNAPSHOT, which I have also deployed to repository.apache.org. Please report back if this resolves the issue.

Show

Kristian Rosenvold added a comment - 03/Nov/10 2:59 PM There is a decent chance this issue was fixed by the fix for SUREFIRE-640 . I am still not able to reproduce this, even if I change the System.out.println as you suggest. Please re-test with 2.7-SNAPSHOT, which I have also deployed to repository.apache.org. Please report back if this resolves the issue.

Hide

Permalink

Michael Hinterseher added a comment - 08/Nov/10 3:34 AM

I tested with 2.7-SNAPSHOT and the problem seems to be solved.

Show

Michael Hinterseher added a comment - 08/Nov/10 3:34 AM I tested with 2.7-SNAPSHOT and the problem seems to be solved.

Hide

Permalink

Gin-Ting Chen added a comment - 25/Jan/11 9:05 AM

This is occurring (again?) with 2.7.1.
This is running m3 with -T 1C (8 core build machine).

[17:52:38]: [ERROR] Failed to execute goal org.apache.maven.plugins:maven-surefire-plugin:2.7.1:test (default-test) on project hornet-stinger: Error while executing forked tests.; nested exception is java.lang.IllegalStateException: testSetCompleted called before testSetStarting -> [Help 1]

Seems like it doesn't happen as frequently as previously

Show

Gin-Ting Chen added a comment - 25/Jan/11 9:05 AM This is occurring (again?) with 2.7.1. This is running m3 with -T 1C (8 core build machine). [17:52:38]: [ERROR] Failed to execute goal org.apache.maven.plugins:maven-surefire-plugin:2.7.1:test ( default -test) on project hornet-stinger: Error while executing forked tests.; nested exception is java.lang.IllegalStateException: testSetCompleted called before testSetStarting -> [Help 1] Seems like it doesn't happen as frequently as previously

Hide

Permalink

Kristian Rosenvold added a comment - 26/Jan/11 4:55 AM

Gin-Ting, although you're right it's "related"; this is actually a separate problem. This issue is related to redirectTestOutputToFile=true and output at the end of the last test in the fork. Please file a separate issue and I will fix it for 2.7.3

Show

Kristian Rosenvold added a comment - 26/Jan/11 4:55 AM Gin-Ting, although you're right it's "related"; this is actually a separate problem. This issue is related to redirectTestOutputToFile=true and output at the end of the last test in the fork. Please file a separate issue and I will fix it for 2.7.3

Hide

Permalink

Gin-Ting Chen added a comment - 26/Jan/11 1:18 PM

Created ~~SUREFIRE-690~~. Thanks Kristian.

Show

Gin-Ting Chen added a comment - 26/Jan/11 1:18 PM Created SUREFIRE-690 . Thanks Kristian.

People

Assignee:

Kristian Rosenvold

Reporter:

Michael Hinterseher

Vote (1)

Watch (2)

Dates

Created:

18/Aug/10 10:52 AM

Updated:

26/Jan/11 1:18 PM

Resolved:

08/Nov/10 3:34 AM