[ 
https://issues.apache.org/jira/browse/SUREFIRE-1244?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15504691#comment-15504691
 ] 

David Carlton commented on SUREFIRE-1244:
-----------------------------------------

Thanks!

> NumberFormatException in parallel test run with runOrder = failedFirst
> ----------------------------------------------------------------------
>
>                 Key: SUREFIRE-1244
>                 URL: https://issues.apache.org/jira/browse/SUREFIRE-1244
>             Project: Maven Surefire
>          Issue Type: Bug
>          Components: Maven Surefire Plugin, process forking
>    Affects Versions: 2.18.1
>            Reporter: David Carlton
>            Assignee: Tibor Digana
>            Priority: Minor
>             Fix For: 2.19.2
>
>
> Occasionally in our Jenkins build, I get an error in test reporting with a 
> backtrace like this:
> {code}
> 13:28:00 [ERROR] Failed to execute goal 
> org.apache.maven.plugins:maven-surefire-plugin:2.18.1:test (default-test) on 
> project service: ExecutionException: java.lang.NumberFormatException: For 
> input string: "pClientWrapperTest)" -> [Help 1]
> 13:28:00 org.apache.maven.lifecycle.LifecycleExecutionException: Failed to 
> execute goal org.apache.maven.plugins:maven-surefire-plugin:2.18.1:test 
> (default-test) on project service: ExecutionException
> 13:28:00      at 
> org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:213)
> 13:28:00      at 
> org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:153)
> 13:28:00      at 
> org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:145)
> 13:28:00      at 
> org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:84)
> 13:28:00      at 
> org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:59)
> 13:28:00      at 
> org.apache.maven.lifecycle.internal.LifecycleStarter.singleThreadedBuild(LifecycleStarter.java:183)
> 13:28:00      at 
> org.apache.maven.lifecycle.internal.LifecycleStarter.execute(LifecycleStarter.java:161)
> 13:28:00      at 
> org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:320)
> 13:28:00      at org.apache.maven.DefaultMaven.execute(DefaultMaven.java:156)
> 13:28:00      at 
> org.jvnet.hudson.maven3.launcher.Maven3Launcher.main(Maven3Launcher.java:117)
> 13:28:00      at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> 13:28:00      at 
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
> 13:28:00      at 
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> 13:28:00      at java.lang.reflect.Method.invoke(Method.java:606)
> 13:28:00      at 
> org.codehaus.plexus.classworlds.launcher.Launcher.launchStandard(Launcher.java:329)
> 13:28:00      at 
> org.codehaus.plexus.classworlds.launcher.Launcher.launch(Launcher.java:239)
> 13:28:00      at 
> org.jvnet.hudson.maven3.agent.Maven3Main.launch(Maven3Main.java:181)
> 13:28:00      at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> 13:28:00      at 
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
> 13:28:00      at 
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> 13:28:00      at java.lang.reflect.Method.invoke(Method.java:606)
> 13:28:00      at hudson.maven.Maven3Builder.call(Maven3Builder.java:136)
> 13:28:00      at hudson.maven.Maven3Builder.call(Maven3Builder.java:71)
> 13:28:00      at hudson.remoting.UserRequest.perform(UserRequest.java:121)
> 13:28:00      at hudson.remoting.UserRequest.perform(UserRequest.java:49)
> 13:28:00      at hudson.remoting.Request$2.run(Request.java:326)
> 13:28:00      at 
> hudson.remoting.InterceptingExecutorService$1.call(InterceptingExecutorService.java:68)
> 13:28:00      at java.util.concurrent.FutureTask.run(FutureTask.java:262)
> 13:28:00      at 
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
> 13:28:00      at 
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> 13:28:00      at java.lang.Thread.run(Thread.java:745)
> 13:28:00 Caused by: org.apache.maven.plugin.MojoFailureException: 
> ExecutionException
> 13:28:00      at 
> org.apache.maven.plugin.surefire.SurefirePlugin.assertNoException(SurefirePlugin.java:262)
> 13:28:00      at 
> org.apache.maven.plugin.surefire.SurefirePlugin.handleSummary(SurefirePlugin.java:252)
> 13:28:00      at 
> org.apache.maven.plugin.surefire.AbstractSurefireMojo.executeAfterPreconditionsChecked(AbstractSurefireMojo.java:854)
> 13:28:00      at 
> org.apache.maven.plugin.surefire.AbstractSurefireMojo.execute(AbstractSurefireMojo.java:722)
> 13:28:00      at 
> org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo(DefaultBuildPluginManager.java:101)
> 13:28:00      at 
> org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:209)
> 13:28:00      ... 30 more
> 13:28:00 Caused by: 
> org.apache.maven.surefire.booter.SurefireBooterForkException: 
> ExecutionException
> 13:28:00      at 
> org.apache.maven.plugin.surefire.booterclient.ForkStarter.runSuitesForkPerTestSet(ForkStarter.java:343)
> 13:28:00      at 
> org.apache.maven.plugin.surefire.booterclient.ForkStarter.run(ForkStarter.java:178)
> 13:28:00      at 
> org.apache.maven.plugin.surefire.AbstractSurefireMojo.executeProvider(AbstractSurefireMojo.java:990)
> 13:28:00      at 
> org.apache.maven.plugin.surefire.AbstractSurefireMojo.executeAfterPreconditionsChecked(AbstractSurefireMojo.java:824)
> 13:28:00      ... 33 more
> 13:28:00 Caused by: java.util.concurrent.ExecutionException: 
> java.lang.NumberFormatException: For input string: "pClientWrapperTest)"
> 13:28:00      at java.util.concurrent.FutureTask.report(FutureTask.java:122)
> 13:28:00      at java.util.concurrent.FutureTask.get(FutureTask.java:188)
> 13:28:00      at 
> org.apache.maven.plugin.surefire.booterclient.ForkStarter.runSuitesForkPerTestSet(ForkStarter.java:327)
> 13:28:00      ... 36 more
> 13:28:00 Caused by: java.lang.NumberFormatException: For input string: 
> "pClientWrapperTest)"
> 13:28:00      at 
> java.lang.NumberFormatException.forInputString(NumberFormatException.java:65)
> 13:28:00      at java.lang.Integer.parseInt(Integer.java:492)
> 13:28:00      at java.lang.Integer.parseInt(Integer.java:527)
> 13:28:00      at 
> org.apache.maven.plugin.surefire.runorder.RunEntryStatistics.fromString(RunEntryStatistics.java:83)
> 13:28:00      at 
> org.apache.maven.plugin.surefire.runorder.RunEntryStatisticsMap.fromReader(RunEntryStatisticsMap.java:91)
> 13:28:00      at 
> org.apache.maven.plugin.surefire.runorder.RunEntryStatisticsMap.fromFile(RunEntryStatisticsMap.java:66)
> 13:28:00      at 
> org.apache.maven.plugin.surefire.runorder.StatisticsReporter.<init>(StatisticsReporter.java:40)
> 13:28:00      at 
> org.apache.maven.plugin.surefire.StartupReportConfiguration.instantiateStatisticsReporter(StartupReportConfiguration.java:214)
> 13:28:00      at 
> org.apache.maven.plugin.surefire.report.DefaultReporterFactory.<init>(DefaultReporterFactory.java:71)
> 13:28:00      at 
> org.apache.maven.plugin.surefire.booterclient.ForkStarter$2.call(ForkStarter.java:309)
> 13:28:00      at 
> org.apache.maven.plugin.surefire.booterclient.ForkStarter$2.call(ForkStarter.java:306)
> 13:28:00      ... 4 more
> 13:28:00 [ERROR] 
> 13:28:00 [ERROR] Re-run Maven using the -X switch to enable full debug 
> logging.
> 13:28:00 [ERROR] 
> {code}
> The details of the backtrace aren't always identical, and it's not even 
> always a {{NumberFormatException}}, but that's the most common symptom.
> Here's my diagnosis: in the above example, it's trying to parse the string 
> {{pClientWrapperTest}} as a number.  And, in fact, we have a test called 
> {{SipClientWrapperTest}} in the project, so it seems like the 
> {{.jenkins-HASH}} file is either getting written to with invalid data or is 
> getting overwritten while we are in the middle of writing.
> Here's our configuration:
> {code}
>       <plugin>
>         <groupId>org.apache.maven.plugins</groupId>
>         <artifactId>maven-surefire-plugin</artifactId>
>         <version>2.18.1</version>
>         <configuration>
>           <argLine>-Djava.awt.headless=true -Xmx1024m -XX:MaxPermSize=256m 
> -XX:+CMSClassUnloadingEnabled -Dsumo.detect.flakiness=false</argLine>
>           <redirectTestOutputToFile>true</redirectTestOutputToFile>
>           <runOrder>failedfirst</runOrder>
>           <trimStackTrace>false</trimStackTrace>
>           <forkCount>1C</forkCount>
>           <reuseForks>false</reuseForks>
>           <systemPropertyVariables>
>             <property>
>               <name>java.io.tmpdir</name>
>               <value>${project.build.directory}</value>
>             </property>
>           </systemPropertyVariables>
>           <includes>
>             <include>**/*Spec.class</include>
>             <include>**/*Suite.class</include>
>             <include>**/*Test.class</include>
>           </includes>
>         </configuration>
>       </plugin>
> {code}
> Note the {{forkCount}} property: we're running tests in parallel (assuming 
> we're on a multicore machine, which we are), but they all write to the same 
> {{.jenkins-HASH}} file because the hash depends on the overall job, not on 
> the individual test classes.
> I haven't looked at the code closely enough to know if multiple tests are 
> writing to the file at the same time, though I haven't been able to catch 
> that in the act, so my guess is that they aren't.  But, if you look at the 
> stacktrace, you'll see that it's going through this method:
> {code}
>     public StatisticsReporter instantiateStatisticsReporter()
>     {
>         if ( requiresRunHistory )
>         {
>             final File target = getStatisticsFile();
>             return new StatisticsReporter( target );
>         }
>         return null;
>     }
> {code}
> and specifically the problem seems to be when it instantiates the 
> {{StatisticsReporter}} at the start of running tests for one class.  Note 
> that if you go up a couple of stack frames, you see this:
> {code}
>             while ( suites.hasNext() )
>             {
>                 final Object testSet = suites.next();
>                 Callable<RunResult> pf = new Callable<RunResult>()
>                 {
>                     public RunResult call()
>                         throws Exception
>                     {
>                         DefaultReporterFactory forkedReporterFactory =
>                             new DefaultReporterFactory( 
> startupReportConfiguration );
>                         defaultReporterFactoryList.add( forkedReporterFactory 
> );
>                         ForkClient forkClient =
>                                         new ForkClient( forkedReporterFactory,
>                                                         
> startupReportConfiguration.getTestVmSystemProperties() );
>                         return fork( testSet, new PropertiesWrapper( 
> providerConfiguration.getProviderProperties() ),
>                                      forkClient, effectiveSystemProperties, 
> null );
>                     }
>                 };
>                 results.add( executorService.submit( pf ) );
>             }
> {code}
> where line 309 is the {{DefaultReporterFactory}} instantiation - so we're 
> creating a bunch of {{Callables}} that are each instantiating a 
> {{DefaultReporterFactory}}, and they're each trying to read the 
> {{.jenkins-HASH}} file; given that, I suspect that one of them is trying to 
> read the file while another one is trying to write it, and so it gets a parse 
> error in the middle of reading.
> It seems like the fix in my situation is to remove the {{runOrder}} value 
> from my configuration - the code only reads the statistics on startup when 
> {{runOrder}} is set to {{failedfirst}} or {{balanced}}, so if I remove that 
> line (setting it to {{filesystem}}) then we won't instantiate a 
> {{StatisticsReporter}} at startup.  I'm not too familiar with that 
> configuration, but it's not at all clear to me that the {{failedfirst}} / 
> {{balanced}} configurations work at all in parallel scenarios?  (We set the 
> {{runOrder}} years ago, while we only turned on the parallel test execution 
> relatively recently.)
> I'm filing this as Minor for now because I suspect I have a workaround, but 
> hopefully this bug will be useful if other people run into the same issue.



--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Reply via email to