New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Unstable TreeWalkerTest during coverage execution #4445

Closed
romani opened this Issue Jun 10, 2017 · 18 comments

Comments

@romani
Member

romani commented Jun 10, 2017

related to #4393.

reported at #4433 (comment)
and at #4442 (comment)

@ps-sp , please rewrite code a bit in UT to avoid such checks of mocks - it is not stable.
Problem could not be resolved by CI relaunch.
@ps-sp , please address this issue ASAP.

@rnveach

This comment has been minimized.

Show comment
Hide comment
@rnveach

rnveach Jun 10, 2017

Member

I played around with issue a little.
Tests pass but code coverage fail.
Printing stack trace in the method only gets printed once.
Removing all other tests does not help.
Moving verifyPrivate(TreeWalker.class, times(1)).invoke("appendHiddenCommentNodes", any(DetailAST.class)) before treeWalkerSpy.processFiltered passes code coverage but fails test.

I think there is some conflict between mockito and cobertura.
It might be related to cobertura/cobertura#133 .

Member

rnveach commented Jun 10, 2017

I played around with issue a little.
Tests pass but code coverage fail.
Printing stack trace in the method only gets printed once.
Removing all other tests does not help.
Moving verifyPrivate(TreeWalker.class, times(1)).invoke("appendHiddenCommentNodes", any(DetailAST.class)) before treeWalkerSpy.processFiltered passes code coverage but fails test.

I think there is some conflict between mockito and cobertura.
It might be related to cobertura/cobertura#133 .

@romani

This comment has been minimized.

Show comment
Hide comment
@romani

romani Jun 10, 2017

Member

it is reproducible on local, but exit code is SUCCESS.

$ mvn verify
....
[Thread-15] INFO net.sourceforge.cobertura.coveragedata.CoverageDataFileHandler - Cobertura: Saved information on 401 classes.
[INFO] 
[INFO] Results:
[INFO] 
[ERROR] Failures: 
[ERROR]   TreeWalkerTest.testBehaviourWithOnlyCommentChecks:328 
com.puppycrawl.tools.checkstyle.TreeWalker.appendHiddenCommentNodes(
    null
);
Wanted 1 time but was 2 times.
[ERROR]   TreeWalkerTest.testBehaviourWithOrdinaryAndCommentChecks:351 
com.puppycrawl.tools.checkstyle.TreeWalker.appendHiddenCommentNodes(
    null
);
Wanted 1 time but was 2 times.
[INFO] 
[ERROR] Tests run: 2100, Failures: 2, Errors: 0, Skipped: 0
[INFO] 
[ERROR] There are test failures.

Please refer to /home/rivanov/java/github/checkstyle/checkstyle/target/surefire-reports for the individual test results.
Please refer to dump files (if any exist) [date]-jvmRun[N].dump, [date].dumpstream and [date]-jvmRun[N].dumpstream.
[INFO] 
[INFO] --- xml-maven-plugin:1.0.1:validate (default) @ checkstyle ---
[INFO] 
[INFO] <<< cobertura-maven-plugin:2.7:check (default) < [cobertura]test @ checkstyle <<<
[INFO] 
[INFO] --- cobertura-maven-plugin:2.7:check (default) @ checkstyle ---
[INFO] All checks passed.
[INFO] ------------------------------------------------------------------------
[INFO] BUILD SUCCESS
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 03:35 min
[INFO] Finished at: 2017-06-09T19:01:30-07:00
[INFO] Final Memory: 101M/1451M

Member

romani commented Jun 10, 2017

it is reproducible on local, but exit code is SUCCESS.

$ mvn verify
....
[Thread-15] INFO net.sourceforge.cobertura.coveragedata.CoverageDataFileHandler - Cobertura: Saved information on 401 classes.
[INFO] 
[INFO] Results:
[INFO] 
[ERROR] Failures: 
[ERROR]   TreeWalkerTest.testBehaviourWithOnlyCommentChecks:328 
com.puppycrawl.tools.checkstyle.TreeWalker.appendHiddenCommentNodes(
    null
);
Wanted 1 time but was 2 times.
[ERROR]   TreeWalkerTest.testBehaviourWithOrdinaryAndCommentChecks:351 
com.puppycrawl.tools.checkstyle.TreeWalker.appendHiddenCommentNodes(
    null
);
Wanted 1 time but was 2 times.
[INFO] 
[ERROR] Tests run: 2100, Failures: 2, Errors: 0, Skipped: 0
[INFO] 
[ERROR] There are test failures.

Please refer to /home/rivanov/java/github/checkstyle/checkstyle/target/surefire-reports for the individual test results.
Please refer to dump files (if any exist) [date]-jvmRun[N].dump, [date].dumpstream and [date]-jvmRun[N].dumpstream.
[INFO] 
[INFO] --- xml-maven-plugin:1.0.1:validate (default) @ checkstyle ---
[INFO] 
[INFO] <<< cobertura-maven-plugin:2.7:check (default) < [cobertura]test @ checkstyle <<<
[INFO] 
[INFO] --- cobertura-maven-plugin:2.7:check (default) @ checkstyle ---
[INFO] All checks passed.
[INFO] ------------------------------------------------------------------------
[INFO] BUILD SUCCESS
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 03:35 min
[INFO] Finished at: 2017-06-09T19:01:30-07:00
[INFO] Final Memory: 101M/1451M

@rnveach

This comment has been minimized.

Show comment
Hide comment
@rnveach

rnveach Jun 10, 2017

Member

Test failure seems to go away for me if I downgrade cobertura-maven-plugin to 2.6

mvn clean cobertura:clean cobertura:cobertura

[INFO] --- cobertura-maven-plugin:2.6:instrument (default-cli) @ checkstyle ---
[INFO] NOT adding cobertura ser file to attached artifacts list.
[INFO] 
[INFO] --- maven-resources-plugin:3.0.2:testResources (default-testResources) @ checkstyle ---
[INFO] Using 'UTF-8' encoding to copy filtered resources.
[INFO] Copying 864 resources
[INFO] 
[INFO] --- maven-compiler-plugin:3.6.1:testCompile (default-testCompile) @ checkstyle ---
[INFO] Changes detected - recompiling the module!
[INFO] Compiling 893 source files to M:\checkstyleWorkspace\checkstyle\target\test-classes
[INFO] 
[INFO] --- maven-surefire-plugin:2.20:test (default-test) @ checkstyle ---
[INFO] 
[INFO] -------------------------------------------------------
[INFO]  T E S T S
[INFO] -------------------------------------------------------
[INFO] Running com.puppycrawl.tools.checkstyle.TreeWalkerTest
[INFO] Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.995 s - in com.puppycrawl.tools.checkstyle.TreeWalkerTest
[INFO] 
[INFO] Results:
[INFO] 
[INFO] Tests run: 1, Failures: 0, Errors: 0, Skipped: 0
[INFO] 
[INFO] 
[INFO] --- xml-maven-plugin:1.0.1:validate (default) @ checkstyle ---
[INFO] 
[INFO] <<< cobertura-maven-plugin:2.6:cobertura (default-cli) < [cobertura]test @ checkstyle <<<
[INFO] 
[INFO] --- cobertura-maven-plugin:2.6:cobertura (default-cli) @ checkstyle ---
[INFO] Cobertura Report generation was successful.
[INFO] Cobertura Report generation was successful.
[INFO] ------------------------------------------------------------------------
[INFO] BUILD SUCCESS
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 21.963 s (Wall Clock)
[INFO] Finished at: 2017-06-09T22:03:30-04:00
[INFO] Final Memory: 40M/173M
[INFO] ------------------------------------------------------------------------
Member

rnveach commented Jun 10, 2017

Test failure seems to go away for me if I downgrade cobertura-maven-plugin to 2.6

mvn clean cobertura:clean cobertura:cobertura

[INFO] --- cobertura-maven-plugin:2.6:instrument (default-cli) @ checkstyle ---
[INFO] NOT adding cobertura ser file to attached artifacts list.
[INFO] 
[INFO] --- maven-resources-plugin:3.0.2:testResources (default-testResources) @ checkstyle ---
[INFO] Using 'UTF-8' encoding to copy filtered resources.
[INFO] Copying 864 resources
[INFO] 
[INFO] --- maven-compiler-plugin:3.6.1:testCompile (default-testCompile) @ checkstyle ---
[INFO] Changes detected - recompiling the module!
[INFO] Compiling 893 source files to M:\checkstyleWorkspace\checkstyle\target\test-classes
[INFO] 
[INFO] --- maven-surefire-plugin:2.20:test (default-test) @ checkstyle ---
[INFO] 
[INFO] -------------------------------------------------------
[INFO]  T E S T S
[INFO] -------------------------------------------------------
[INFO] Running com.puppycrawl.tools.checkstyle.TreeWalkerTest
[INFO] Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.995 s - in com.puppycrawl.tools.checkstyle.TreeWalkerTest
[INFO] 
[INFO] Results:
[INFO] 
[INFO] Tests run: 1, Failures: 0, Errors: 0, Skipped: 0
[INFO] 
[INFO] 
[INFO] --- xml-maven-plugin:1.0.1:validate (default) @ checkstyle ---
[INFO] 
[INFO] <<< cobertura-maven-plugin:2.6:cobertura (default-cli) < [cobertura]test @ checkstyle <<<
[INFO] 
[INFO] --- cobertura-maven-plugin:2.6:cobertura (default-cli) @ checkstyle ---
[INFO] Cobertura Report generation was successful.
[INFO] Cobertura Report generation was successful.
[INFO] ------------------------------------------------------------------------
[INFO] BUILD SUCCESS
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 21.963 s (Wall Clock)
[INFO] Finished at: 2017-06-09T22:03:30-04:00
[INFO] Final Memory: 40M/173M
[INFO] ------------------------------------------------------------------------
@romani

This comment has been minimized.

Show comment
Hide comment
@romani

romani Jun 10, 2017

Member

one travis buils is failed with more severe crash:

[INFO] Running com.puppycrawl.tools.checkstyle.TreeWalkerTest
SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in [jar:file:/home/travis/.m2/repository/org/slf4j/slf4j-simple/1.7.25/slf4j-simple-1.7.25.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in [jar:file:/home/travis/.m2/repository/ch/qos/logback/logback-classic/1.0.13/logback-classic-1.0.13.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
SLF4J: Actual binding is of type [org.slf4j.impl.SimpleLoggerFactory]
[INFO] 
[INFO] Results:
[INFO] 
[INFO] Tests run: 2071, Failures: 0, Errors: 0, Skipped: 0
[INFO] 
[ERROR] There are test failures.
Please refer to /home/travis/build/checkstyle/checkstyle/target/surefire-reports for the individual test results.
Please refer to dump files (if any exist) [date]-jvmRun[N].dump, [date].dumpstream and [date]-jvmRun[N].dumpstream.
The forked VM terminated without properly saying goodbye. VM crash or System.exit called?
Command was /bin/sh -c cd /home/travis/build/checkstyle/checkstyle && /usr/lib/jvm/java-8-oracle/jre/bin/java -jar /home/travis/build/checkstyle/checkstyle/target/surefire/surefirebooter5807404614326026615.jar /home/travis/build/checkstyle/checkstyle/target/surefire 2017-06-10T01-55-16_277-jvmRun1 surefire9098863970526065943tmp surefire_07904162880634151490tmp
Error occurred in starting fork, check output in log
Process Exit Code: 137
Crashed tests:
com.puppycrawl.tools.checkstyle.TreeWalkerTest
org.apache.maven.surefire.booter.SurefireBooterForkException: The forked VM terminated without properly saying goodbye. VM crash or System.exit called?
Command was /bin/sh -c cd /home/travis/build/checkstyle/checkstyle && /usr/lib/jvm/java-8-oracle/jre/bin/java -jar /home/travis/build/checkstyle/checkstyle/target/surefire/surefirebooter5807404614326026615.jar /home/travis/build/checkstyle/checkstyle/target/surefire 2017-06-10T01-55-16_277-jvmRun1 surefire9098863970526065943tmp surefire_07904162880634151490tmp
Error occurred in starting fork, check output in log
Process Exit Code: 137
Crashed tests:
com.puppycrawl.tools.checkstyle.TreeWalkerTest
    at org.apache.maven.plugin.surefire.booterclient.ForkStarter.fork(ForkStarter.java:679)
    at org.apache.maven.plugin.surefire.booterclient.ForkStarter.fork(ForkStarter.java:533)
    at org.apache.maven.plugin.surefire.booterclient.ForkStarter.run(ForkStarter.java:279)
    at org.apache.maven.plugin.surefire.booterclient.ForkStarter.run(ForkStarter.java:243)
    at org.apache.maven.plugin.surefire.AbstractSurefireMojo.executeProvider(AbstractSurefireMojo.java:1077)
    at org.apache.maven.plugin.surefire.AbstractSurefireMojo.executeAfterPreconditionsChecked(AbstractSurefireMojo.java:907)
    at org.apache.maven.plugin.surefire.AbstractSurefireMojo.execute(AbstractSurefireMojo.java:785)
    at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo(DefaultBuildPluginManager.java:132)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:208)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:153)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:145)
    at org.apache.maven.lifecycle.internal.MojoExecutor.executeForkedExecutions(MojoExecutor.java:364)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:198)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:153)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:145)
    at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:116)
    at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:80)
    at org.apache.maven.lifecycle.internal.builder.singlethreaded.SingleThreadedBuilder.build(SingleThreadedBuilder.java:51)
    at org.apache.maven.lifecycle.internal.LifecycleStarter.execute(LifecycleStarter.java:120)
    at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:355)
    at org.apache.maven.DefaultMaven.execute(DefaultMaven.java:155)
    at org.apache.maven.cli.MavenCli.execute(MavenCli.java:584)
    at org.apache.maven.cli.MavenCli.doMain(MavenCli.java:216)
    at org.apache.maven.cli.MavenCli.main(MavenCli.java:160)
    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)
[INFO] 
[INFO] --- xml-maven-plugin:1.0.1:validate (default) @ checkstyle ---
[INFO] 
[INFO] <<< cobertura-maven-plugin:2.7:check (default-cli) < [cobertura]test @ checkstyle <<<
[INFO] 
[INFO] --- cobertura-maven-plugin:2.7:check (default-cli) @ checkstyle ---
[INFO] ------------------------------------------------------------------------
[INFO] BUILD FAILURE
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 01:47 min
[INFO] Finished at: 2017-06-10T01:56:38+00:00
[INFO] Final Memory: 52M/473M
[INFO] ------------------------------------------------------------------------
[ERROR] Failed to execute goal org.codehaus.mojo:cobertura-maven-plugin:2.7:check (default-cli) on project checkstyle: Coverage check failed. See messages above. -> [Help 1]
[ERROR] 
[ERROR] To see the full stack trace of the errors, re-run Maven with the -e switch.
[ERROR] Re-run Maven using the -X switch to enable full debug logging.
[ERROR] 
[ERROR] For more information about the errors and possible solutions, please read the following articles:
[ERROR] [Help 1] http://cwiki.apache.org/confluence/display/MAVEN/MojoFailureException
Member

romani commented Jun 10, 2017

one travis buils is failed with more severe crash:

[INFO] Running com.puppycrawl.tools.checkstyle.TreeWalkerTest
SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in [jar:file:/home/travis/.m2/repository/org/slf4j/slf4j-simple/1.7.25/slf4j-simple-1.7.25.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in [jar:file:/home/travis/.m2/repository/ch/qos/logback/logback-classic/1.0.13/logback-classic-1.0.13.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
SLF4J: Actual binding is of type [org.slf4j.impl.SimpleLoggerFactory]
[INFO] 
[INFO] Results:
[INFO] 
[INFO] Tests run: 2071, Failures: 0, Errors: 0, Skipped: 0
[INFO] 
[ERROR] There are test failures.
Please refer to /home/travis/build/checkstyle/checkstyle/target/surefire-reports for the individual test results.
Please refer to dump files (if any exist) [date]-jvmRun[N].dump, [date].dumpstream and [date]-jvmRun[N].dumpstream.
The forked VM terminated without properly saying goodbye. VM crash or System.exit called?
Command was /bin/sh -c cd /home/travis/build/checkstyle/checkstyle && /usr/lib/jvm/java-8-oracle/jre/bin/java -jar /home/travis/build/checkstyle/checkstyle/target/surefire/surefirebooter5807404614326026615.jar /home/travis/build/checkstyle/checkstyle/target/surefire 2017-06-10T01-55-16_277-jvmRun1 surefire9098863970526065943tmp surefire_07904162880634151490tmp
Error occurred in starting fork, check output in log
Process Exit Code: 137
Crashed tests:
com.puppycrawl.tools.checkstyle.TreeWalkerTest
org.apache.maven.surefire.booter.SurefireBooterForkException: The forked VM terminated without properly saying goodbye. VM crash or System.exit called?
Command was /bin/sh -c cd /home/travis/build/checkstyle/checkstyle && /usr/lib/jvm/java-8-oracle/jre/bin/java -jar /home/travis/build/checkstyle/checkstyle/target/surefire/surefirebooter5807404614326026615.jar /home/travis/build/checkstyle/checkstyle/target/surefire 2017-06-10T01-55-16_277-jvmRun1 surefire9098863970526065943tmp surefire_07904162880634151490tmp
Error occurred in starting fork, check output in log
Process Exit Code: 137
Crashed tests:
com.puppycrawl.tools.checkstyle.TreeWalkerTest
    at org.apache.maven.plugin.surefire.booterclient.ForkStarter.fork(ForkStarter.java:679)
    at org.apache.maven.plugin.surefire.booterclient.ForkStarter.fork(ForkStarter.java:533)
    at org.apache.maven.plugin.surefire.booterclient.ForkStarter.run(ForkStarter.java:279)
    at org.apache.maven.plugin.surefire.booterclient.ForkStarter.run(ForkStarter.java:243)
    at org.apache.maven.plugin.surefire.AbstractSurefireMojo.executeProvider(AbstractSurefireMojo.java:1077)
    at org.apache.maven.plugin.surefire.AbstractSurefireMojo.executeAfterPreconditionsChecked(AbstractSurefireMojo.java:907)
    at org.apache.maven.plugin.surefire.AbstractSurefireMojo.execute(AbstractSurefireMojo.java:785)
    at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo(DefaultBuildPluginManager.java:132)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:208)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:153)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:145)
    at org.apache.maven.lifecycle.internal.MojoExecutor.executeForkedExecutions(MojoExecutor.java:364)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:198)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:153)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:145)
    at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:116)
    at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:80)
    at org.apache.maven.lifecycle.internal.builder.singlethreaded.SingleThreadedBuilder.build(SingleThreadedBuilder.java:51)
    at org.apache.maven.lifecycle.internal.LifecycleStarter.execute(LifecycleStarter.java:120)
    at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:355)
    at org.apache.maven.DefaultMaven.execute(DefaultMaven.java:155)
    at org.apache.maven.cli.MavenCli.execute(MavenCli.java:584)
    at org.apache.maven.cli.MavenCli.doMain(MavenCli.java:216)
    at org.apache.maven.cli.MavenCli.main(MavenCli.java:160)
    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)
[INFO] 
[INFO] --- xml-maven-plugin:1.0.1:validate (default) @ checkstyle ---
[INFO] 
[INFO] <<< cobertura-maven-plugin:2.7:check (default-cli) < [cobertura]test @ checkstyle <<<
[INFO] 
[INFO] --- cobertura-maven-plugin:2.7:check (default-cli) @ checkstyle ---
[INFO] ------------------------------------------------------------------------
[INFO] BUILD FAILURE
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 01:47 min
[INFO] Finished at: 2017-06-10T01:56:38+00:00
[INFO] Final Memory: 52M/473M
[INFO] ------------------------------------------------------------------------
[ERROR] Failed to execute goal org.codehaus.mojo:cobertura-maven-plugin:2.7:check (default-cli) on project checkstyle: Coverage check failed. See messages above. -> [Help 1]
[ERROR] 
[ERROR] To see the full stack trace of the errors, re-run Maven with the -e switch.
[ERROR] Re-run Maven using the -X switch to enable full debug logging.
[ERROR] 
[ERROR] For more information about the errors and possible solutions, please read the following articles:
[ERROR] [Help 1] http://cwiki.apache.org/confluence/display/MAVEN/MojoFailureException
@ps-sp

This comment has been minimized.

Show comment
Hide comment
@ps-sp

ps-sp Jun 11, 2017

Collaborator

@romani @rnveach mvn test has no failures which only makes me think that somehow cobertura is invoking that function 1 extra time for testing something. There seem to be no issue checking private method walk or static method parse. The problem seems to be only with the private static method appendHiddenCommentNodes. I tried passing the spy object treeWalkerSpy to verifyPrivate call which verifies calls to appendHiddenCommentNodes but I was getting mockito exception about unfinished verification, UnfinishedVerificationException, which didn't make much sense and I wasn't able to get rid of it.

All that said, for now we can just get rid of checking calls to appendHiddenCommentNodes as this is causing problems for CIs

Collaborator

ps-sp commented Jun 11, 2017

@romani @rnveach mvn test has no failures which only makes me think that somehow cobertura is invoking that function 1 extra time for testing something. There seem to be no issue checking private method walk or static method parse. The problem seems to be only with the private static method appendHiddenCommentNodes. I tried passing the spy object treeWalkerSpy to verifyPrivate call which verifies calls to appendHiddenCommentNodes but I was getting mockito exception about unfinished verification, UnfinishedVerificationException, which didn't make much sense and I wasn't able to get rid of it.

All that said, for now we can just get rid of checking calls to appendHiddenCommentNodes as this is causing problems for CIs

ps-sp added a commit to ps-sp/checkstyle that referenced this issue Jun 11, 2017

Issue checkstyle#4445: Verifying calls to private static method using…
… powermock was causing CI failures due to apparent conflict with cobertura
@rnveach

This comment has been minimized.

Show comment
Hide comment
@rnveach

rnveach Jun 11, 2017

Member

The problem seems to be only with the private static method

Did we add these types of mocks anywhere else that we may need to be concerned with?

Member

rnveach commented Jun 11, 2017

The problem seems to be only with the private static method

Did we add these types of mocks anywhere else that we may need to be concerned with?

@rnveach

This comment has been minimized.

Show comment
Hide comment
@rnveach

rnveach Jun 11, 2017

Member

The problem seems to be only with the private static method

Changing the method to public static and public non-static did not change the failure, but it did cause the error to show up in mvn verify mode.

Failure with public non-static:

[ERROR] Failures: 
[ERROR]   TreeWalkerTest.testBehaviourWithOnlyCommentChecks:68 
treeWalker.appendHiddenCommentNodes(null);
Wanted 1 time:
-> at com.puppycrawl.tools.checkstyle.TreeWalkerTest.testBehaviourWithOnlyCommentChecks(TreeWalkerTest.java:68)
But was 2 times. Undesired invocation:
-> at com.puppycrawl.tools.checkstyle.TreeWalkerTest.testBehaviourWithOnlyCommentChecks(TreeWalkerTest.java:66)
Member

rnveach commented Jun 11, 2017

The problem seems to be only with the private static method

Changing the method to public static and public non-static did not change the failure, but it did cause the error to show up in mvn verify mode.

Failure with public non-static:

[ERROR] Failures: 
[ERROR]   TreeWalkerTest.testBehaviourWithOnlyCommentChecks:68 
treeWalker.appendHiddenCommentNodes(null);
Wanted 1 time:
-> at com.puppycrawl.tools.checkstyle.TreeWalkerTest.testBehaviourWithOnlyCommentChecks(TreeWalkerTest.java:68)
But was 2 times. Undesired invocation:
-> at com.puppycrawl.tools.checkstyle.TreeWalkerTest.testBehaviourWithOnlyCommentChecks(TreeWalkerTest.java:66)
@rnveach

This comment has been minimized.

Show comment
Hide comment
@rnveach

rnveach Jun 11, 2017

Member

@ps-sp I am stepping through .invoke("appendHiddenCommentNodes" of the line

        verifyPrivate(treeWalkerSpy, times(1))
                .invoke("appendHiddenCommentNodes", any(DetailAST.class))
                ;

And it seems that is your second invocation. It goes all the way to WhiteboxImpl.performMethodInvocation and is calling the method directly.
I don't know why private static was hiding this, but public non-static is showing the issue clearer.

List of invocations on line above:

[com.puppycrawl.tools.checkstyle.TreeWalker.configure(
    com.puppycrawl.tools.checkstyle.DefaultConfiguration@1f8a9d3
);,
treeWalker.finishLocalSetup();,
com.puppycrawl.tools.checkstyle.TreeWalker.getMessageCollector();, 
com.puppycrawl.tools.checkstyle.TreeWalker.getSeverity();, 
treeWalker.setModuleFactory(
    com.puppycrawl.tools.checkstyle.PackageObjectFactory@ea2003
);, 
treeWalker.setupChild(
    com.puppycrawl.tools.checkstyle.DefaultConfiguration@11e7ad3
);, 
com.puppycrawl.tools.checkstyle.TreeWalker.registerCheck(
    com.puppycrawl.tools.checkstyle.checks.indentation.CommentsIndentationCheck@82c44a
);, 
com.puppycrawl.tools.checkstyle.TreeWalker.registerCheck(
    144,
    com.puppycrawl.tools.checkstyle.checks.indentation.CommentsIndentationCheck@82c44a
);, 
com.puppycrawl.tools.checkstyle.TreeWalker.registerCheck(
    "SINGLE_LINE_COMMENT",
    com.puppycrawl.tools.checkstyle.checks.indentation.CommentsIndentationCheck@82c44a
);, 
com.puppycrawl.tools.checkstyle.TreeWalker.registerCheck(
    145,
    com.puppycrawl.tools.checkstyle.checks.indentation.CommentsIndentationCheck@82c44a
);, 
com.puppycrawl.tools.checkstyle.TreeWalker.registerCheck(
    "BLOCK_COMMENT_BEGIN",
    com.puppycrawl.tools.checkstyle.checks.indentation.CommentsIndentationCheck@82c44a
);, 
treeWalker.appendHiddenCommentNodes(null);, 
treeWalker.processFiltered(
    C:\Users\Ricky\AppData\Local\Temp\junit4585345914082579554\file.java,
    []
);, 
treeWalker.getFileExtensions();, 
com.puppycrawl.tools.checkstyle.TreeWalker.getMessageCollector();, 
treeWalker.appendHiddenCommentNodes(null);, 
com.puppycrawl.tools.checkstyle.TreeWalker.walk(
    null,
    com.puppycrawl.tools.checkstyle.api.FileContents@1e5e5b4,
    WITH_COMMENTS
);]

As seen appendHiddenCommentNodes is called before we even call processFiltered.

Member

rnveach commented Jun 11, 2017

@ps-sp I am stepping through .invoke("appendHiddenCommentNodes" of the line

        verifyPrivate(treeWalkerSpy, times(1))
                .invoke("appendHiddenCommentNodes", any(DetailAST.class))
                ;

And it seems that is your second invocation. It goes all the way to WhiteboxImpl.performMethodInvocation and is calling the method directly.
I don't know why private static was hiding this, but public non-static is showing the issue clearer.

List of invocations on line above:

[com.puppycrawl.tools.checkstyle.TreeWalker.configure(
    com.puppycrawl.tools.checkstyle.DefaultConfiguration@1f8a9d3
);,
treeWalker.finishLocalSetup();,
com.puppycrawl.tools.checkstyle.TreeWalker.getMessageCollector();, 
com.puppycrawl.tools.checkstyle.TreeWalker.getSeverity();, 
treeWalker.setModuleFactory(
    com.puppycrawl.tools.checkstyle.PackageObjectFactory@ea2003
);, 
treeWalker.setupChild(
    com.puppycrawl.tools.checkstyle.DefaultConfiguration@11e7ad3
);, 
com.puppycrawl.tools.checkstyle.TreeWalker.registerCheck(
    com.puppycrawl.tools.checkstyle.checks.indentation.CommentsIndentationCheck@82c44a
);, 
com.puppycrawl.tools.checkstyle.TreeWalker.registerCheck(
    144,
    com.puppycrawl.tools.checkstyle.checks.indentation.CommentsIndentationCheck@82c44a
);, 
com.puppycrawl.tools.checkstyle.TreeWalker.registerCheck(
    "SINGLE_LINE_COMMENT",
    com.puppycrawl.tools.checkstyle.checks.indentation.CommentsIndentationCheck@82c44a
);, 
com.puppycrawl.tools.checkstyle.TreeWalker.registerCheck(
    145,
    com.puppycrawl.tools.checkstyle.checks.indentation.CommentsIndentationCheck@82c44a
);, 
com.puppycrawl.tools.checkstyle.TreeWalker.registerCheck(
    "BLOCK_COMMENT_BEGIN",
    com.puppycrawl.tools.checkstyle.checks.indentation.CommentsIndentationCheck@82c44a
);, 
treeWalker.appendHiddenCommentNodes(null);, 
treeWalker.processFiltered(
    C:\Users\Ricky\AppData\Local\Temp\junit4585345914082579554\file.java,
    []
);, 
treeWalker.getFileExtensions();, 
com.puppycrawl.tools.checkstyle.TreeWalker.getMessageCollector();, 
treeWalker.appendHiddenCommentNodes(null);, 
com.puppycrawl.tools.checkstyle.TreeWalker.walk(
    null,
    com.puppycrawl.tools.checkstyle.api.FileContents@1e5e5b4,
    WITH_COMMENTS
);]

As seen appendHiddenCommentNodes is called before we even call processFiltered.

@rnveach

This comment has been minimized.

Show comment
Hide comment
@rnveach

rnveach Jun 11, 2017

Member

@ps-sp I removed the following code,

        when(TreeWalker.class, "appendHiddenCommentNodes", any(DetailAST.class))
                .thenReturn(null);

and cobertura and tests passed for me. Can you confirm?
There may be a hidden conflict with cobertua and mockito on static methods, but the underlying failure seems like an issue with mockito to me. It is like it is not knowing the difference between it's own verification calls and a production code call.

Member

rnveach commented Jun 11, 2017

@ps-sp I removed the following code,

        when(TreeWalker.class, "appendHiddenCommentNodes", any(DetailAST.class))
                .thenReturn(null);

and cobertura and tests passed for me. Can you confirm?
There may be a hidden conflict with cobertua and mockito on static methods, but the underlying failure seems like an issue with mockito to me. It is like it is not knowing the difference between it's own verification calls and a production code call.

@rnveach

This comment has been minimized.

Show comment
Hide comment
@rnveach

rnveach Jun 11, 2017

Member

The correct way to make the call may be:

doReturn(null).when(TreeWalker.class, "appendHiddenCommentNodes", any(DetailAST.class));

As talked about at https://stackoverflow.com/a/25018443/1016482 .
This way passes for me too in verify and cobertura.

Member

rnveach commented Jun 11, 2017

The correct way to make the call may be:

doReturn(null).when(TreeWalker.class, "appendHiddenCommentNodes", any(DetailAST.class));

As talked about at https://stackoverflow.com/a/25018443/1016482 .
This way passes for me too in verify and cobertura.

@ps-sp

This comment has been minimized.

Show comment
Hide comment
@ps-sp

ps-sp Jun 11, 2017

Collaborator

Did we add these types of mocks anywhere else that we may need to be concerned with?

I couldn't find any other calls to verifyPrivate. So probably not.

I am stepping through .invoke("appendHiddenCommentNodes" of the line.

That seems to be the proper way we are to verify calls private methods probably. Had read up about this approach on some blog.

I removed the following code...

Yes, You are correct. Removing the code solves this issue. The interesting thing is I had tried using
when(TreeWalker.class, "appendHiddenCommentNodes", any(DetailAST.class)) .thenCallRealMethod(); which doesn't work. Removing that line appeared equivalent to thenCallRealMethod to me but perhaps there is some catch.

but the underlying failure seems like an issue with mockito to me. It is like it is not knowing the difference between it's own verification calls and a production code call.

But why were the tests passing and only cobertura was failing. If it was mistakenly counting its own verification calls then even the tests should have failed. Also, as you noted, there are no problems with a different version of cobertura, which makes me doubt that this issue is primarily due to some conflict with cobertura

doReturn(null).when(TreeWalker.class, "appendHiddenCommentNodes", any(DetailAST.class));
Correct again. This also solves the issue.

I feel it is best to remove this line altogether: when(TreeWalker.class, "appendHiddenCommentNodes", any(DetailAST.class)).thenReturn(null);

Collaborator

ps-sp commented Jun 11, 2017

Did we add these types of mocks anywhere else that we may need to be concerned with?

I couldn't find any other calls to verifyPrivate. So probably not.

I am stepping through .invoke("appendHiddenCommentNodes" of the line.

That seems to be the proper way we are to verify calls private methods probably. Had read up about this approach on some blog.

I removed the following code...

Yes, You are correct. Removing the code solves this issue. The interesting thing is I had tried using
when(TreeWalker.class, "appendHiddenCommentNodes", any(DetailAST.class)) .thenCallRealMethod(); which doesn't work. Removing that line appeared equivalent to thenCallRealMethod to me but perhaps there is some catch.

but the underlying failure seems like an issue with mockito to me. It is like it is not knowing the difference between it's own verification calls and a production code call.

But why were the tests passing and only cobertura was failing. If it was mistakenly counting its own verification calls then even the tests should have failed. Also, as you noted, there are no problems with a different version of cobertura, which makes me doubt that this issue is primarily due to some conflict with cobertura

doReturn(null).when(TreeWalker.class, "appendHiddenCommentNodes", any(DetailAST.class));
Correct again. This also solves the issue.

I feel it is best to remove this line altogether: when(TreeWalker.class, "appendHiddenCommentNodes", any(DetailAST.class)).thenReturn(null);

ps-sp added a commit to ps-sp/checkstyle that referenced this issue Jun 11, 2017

Issue checkstyle#4445: Verifying calls to private static method using…
… powermock was causing CI failures due to apparent conflict with cobertura
@rnveach

This comment has been minimized.

Show comment
Hide comment
@rnveach

rnveach Jun 11, 2017

Member

I feel it is best to remove this line altogether

Make the update in the PR then. I am fine with this since not overriding the method creates no issues.

But why were the tests passing and only cobertura was failing.

I can't debug with cobertura in Eclipse so I can't say what is fully the issue.
Right now, I feel there is a double issue in both mockito and cobertura which was just causing cascading failures during cobertura run. mockito didn't fail tests until I made method public and non-static. cobertura passed when downgrading, which makes me believe they changed the way they modified class between versions.

Both utils are modifying the loaded class in memory at the same time. Cobertura did something to TreeWalker/TreeWalkerTest in memory that caused mockito to behave differently which caused it to fail. But whatever it did, cobertura's changes was more like a fix for mockito as the test should fail, imo. This is what we see when we make the method public and non-static.
Another interesting thing is that the PR for the original code (#4418) did not fail in either one. So somehow this only took affect after another change, but I trimmed down the project to only this test and it was still an issue.

We may be able to learn more if we could dump the entire class' instructions to a file at runtime and analzye it, but I don't see a reason for us to do this if we have a fix ready.

Going forward, we should probably be cautious of mocking static methods.

Member

rnveach commented Jun 11, 2017

I feel it is best to remove this line altogether

Make the update in the PR then. I am fine with this since not overriding the method creates no issues.

But why were the tests passing and only cobertura was failing.

I can't debug with cobertura in Eclipse so I can't say what is fully the issue.
Right now, I feel there is a double issue in both mockito and cobertura which was just causing cascading failures during cobertura run. mockito didn't fail tests until I made method public and non-static. cobertura passed when downgrading, which makes me believe they changed the way they modified class between versions.

Both utils are modifying the loaded class in memory at the same time. Cobertura did something to TreeWalker/TreeWalkerTest in memory that caused mockito to behave differently which caused it to fail. But whatever it did, cobertura's changes was more like a fix for mockito as the test should fail, imo. This is what we see when we make the method public and non-static.
Another interesting thing is that the PR for the original code (#4418) did not fail in either one. So somehow this only took affect after another change, but I trimmed down the project to only this test and it was still an issue.

We may be able to learn more if we could dump the entire class' instructions to a file at runtime and analzye it, but I don't see a reason for us to do this if we have a fix ready.

Going forward, we should probably be cautious of mocking static methods.

rnveach added a commit that referenced this issue Jun 11, 2017

Issue #4445: Verifying calls to private static method using powermock…
… was causing CI failures due to apparent conflict with cobertura
@rnveach

This comment has been minimized.

Show comment
Hide comment
@rnveach

rnveach Jun 11, 2017

Member

@romani Feel free to look over our discussion and re-open this if you have any complaints.

Member

rnveach commented Jun 11, 2017

@romani Feel free to look over our discussion and re-open this if you have any complaints.

@rnveach rnveach closed this Jun 11, 2017

@ps-sp

This comment has been minimized.

Show comment
Hide comment
@ps-sp

ps-sp Jun 12, 2017

Collaborator
  1. public static appendHiddenCommentNodes

Works for me like this:

mockStatic(TreeWalker.class)
verifyStatic(times(1))
TreeWalker.appendHiddenCommentNodes(any(DetailAST.class))
  1. private appendHiddenCommentNodes

Works for me by passing treeWalkerSpy instead of TreeWalker.Class in calls to verifyPrivate and when

i.e like this:

when(treeWalkerSpy, "appendHiddenCommentNodes", any(DetailAST.class))
            .thenReturn(null);
verifyPrivate(treeWalkerSpy, times(1))
    .invoke("appendHiddenCommentNodes", any(DetailAST.class));
  1. public appendHiddenCommentNodes //public non-static

Works for me like this:

when(treeWalkerSpy.appendHiddenCommentNodes(any(DetailAST.class)))
    .thenReturn(null);
Mockito.verify(treeWalkerSpy, times(1))
    .appendHiddenCommentNodes(any(DetailAST.class));

And interestingly public and non-static version of appendHiddenCommentNodes can also be verified using verifyPrivate using the same approach as for private methods and passing treeWalkerSpy instead of TreeWalker.class as argument and cobertura passes. One is to take care to not supply XYZ.class objects for non-static methods and supply the corresponding spy object

mockito didn't fail tests until I made method public and non-static.

So, does mockito even fail for you if you verify it this way ? Were you getting an IllegalArgumentException ? I feel cobertura and powermock have conflicts when we supply XYZ.class as arg to verifyPrivate, but of course the facts we have are pretty far from inconclusive and yes, perhaps it's not worthwhile to ponder this further.

Collaborator

ps-sp commented Jun 12, 2017

  1. public static appendHiddenCommentNodes

Works for me like this:

mockStatic(TreeWalker.class)
verifyStatic(times(1))
TreeWalker.appendHiddenCommentNodes(any(DetailAST.class))
  1. private appendHiddenCommentNodes

Works for me by passing treeWalkerSpy instead of TreeWalker.Class in calls to verifyPrivate and when

i.e like this:

when(treeWalkerSpy, "appendHiddenCommentNodes", any(DetailAST.class))
            .thenReturn(null);
verifyPrivate(treeWalkerSpy, times(1))
    .invoke("appendHiddenCommentNodes", any(DetailAST.class));
  1. public appendHiddenCommentNodes //public non-static

Works for me like this:

when(treeWalkerSpy.appendHiddenCommentNodes(any(DetailAST.class)))
    .thenReturn(null);
Mockito.verify(treeWalkerSpy, times(1))
    .appendHiddenCommentNodes(any(DetailAST.class));

And interestingly public and non-static version of appendHiddenCommentNodes can also be verified using verifyPrivate using the same approach as for private methods and passing treeWalkerSpy instead of TreeWalker.class as argument and cobertura passes. One is to take care to not supply XYZ.class objects for non-static methods and supply the corresponding spy object

mockito didn't fail tests until I made method public and non-static.

So, does mockito even fail for you if you verify it this way ? Were you getting an IllegalArgumentException ? I feel cobertura and powermock have conflicts when we supply XYZ.class as arg to verifyPrivate, but of course the facts we have are pretty far from inconclusive and yes, perhaps it's not worthwhile to ponder this further.

@rnveach

This comment has been minimized.

Show comment
Hide comment
@rnveach

rnveach Jun 12, 2017

Member

Were you getting an IllegalArgumentException ?

No. The test failure I got is at #4445 (comment) .
I did make minor modifications to the test only to work with non-static. See rnveach@4d1f237 .
I didn't really think about the fact that I am using verifyPrivate with a public method.

I feel cobertura and powermock have conflicts when we supply XYZ.class as arg to verifyPrivate

I don't feel this way since it wasn't verifyPrivate that we changed. It was just the one notifying us of the failure.
As shown in the method call log at #4445 (comment) , and the code we changed and merged, it was the when().then that was causing the issue as it was calling the method and increasing the call count.

Member

rnveach commented Jun 12, 2017

Were you getting an IllegalArgumentException ?

No. The test failure I got is at #4445 (comment) .
I did make minor modifications to the test only to work with non-static. See rnveach@4d1f237 .
I didn't really think about the fact that I am using verifyPrivate with a public method.

I feel cobertura and powermock have conflicts when we supply XYZ.class as arg to verifyPrivate

I don't feel this way since it wasn't verifyPrivate that we changed. It was just the one notifying us of the failure.
As shown in the method call log at #4445 (comment) , and the code we changed and merged, it was the when().then that was causing the issue as it was calling the method and increasing the call count.

@ps-sp

This comment has been minimized.

Show comment
Hide comment
@ps-sp

ps-sp Jun 12, 2017

Collaborator
Collaborator

ps-sp commented Jun 12, 2017

@romani

This comment has been minimized.

Show comment
Hide comment
@romani

romani Jun 12, 2017

Member

@rnveach and @ps-sp , sorry was off for two days, did you resolve a problem ? do you need smth from me ?

Member

romani commented Jun 12, 2017

@rnveach and @ps-sp , sorry was off for two days, did you resolve a problem ? do you need smth from me ?

@rnveach

This comment has been minimized.

Show comment
Hide comment
@rnveach

rnveach Jun 12, 2017

Member

@romani The problem should be resolved.

Member

rnveach commented Jun 12, 2017

@romani The problem should be resolved.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment