Standard output listener does not capture the correct test retry count

Help/Discuss
1

Hi Everyone,

We are using testng & gradle to run our integration tests writtne in Java. In our code, we implemented the retry listener base on Martin Holladay’s blog post (https://martinholladay.wordpress.com/2013/11/17/webdriver-2-0-automatically-retry-failed-tests/). However, in the console output, the count is wrong and even the test got retried and pass, it will still mark the whole test as fail in stdout. Here’s a sample log:

18:10:25.401 [DEBUG] [TestEventLogger] 
18:10:25.401 [DEBUG] [TestEventLogger] Gradle Test Executor 1 STARTED
18:10:25.894 [DEBUG] [TestEventLogger] 
18:10:25.894 [DEBUG] [TestEventLogger] retry tests STARTED
18:10:25.906 [DEBUG] [TestEventLogger] 
18:10:25.906 [DEBUG] [TestEventLogger] retry tests >     com.trulia.regression.tests.retrytests.RetryTest.test1 STARTED
18:10:25.913 [QUIET] [system.out] 18:10:25.913 [QUIET] [system.out] 2015-06-15 18:10:25 INFO  RetryTest:24 - time: 1434417025910
18:10:25.914 [QUIET] [system.out] 18:10:25.914 [QUIET] [system.out] 2015-06-15 18:10:25 INFO  RetryTest:25 - modValue: 0
18:10:25.918 [QUIET] [system.out] 18:10:25.917 [QUIET] [system.out] 2015-06-15 18:10:25 INFO  RetryTest:24 - time: 1434417025917
18:10:25.918 [QUIET] [system.out] 18:10:25.918 [QUIET] [system.out] 2015-06-15 18:10:25 INFO  RetryTest:25 - modValue: 1
18:10:25.919 [QUIET] [system.out] 18:10:25.919 [QUIET] [system.out] 2015-06-15 18:10:25 INFO  TestListener:17 - =======> inside TestListener.onFinish
18:10:25.920 [QUIET] [system.out] 18:10:25.920 [QUIET] [system.out] 2015-06-15 18:10:25 INFO  TestListener:40 - fail test count: 1
18:10:25.921 [QUIET] [system.out] 18:10:25.921 [QUIET] [system.out] 2015-06-15 18:10:25 INFO  TestListener:41 - pass test count: 1
18:10:25.922 [QUIET] [system.out] 18:10:25.922 [QUIET] [system.out] 2015-06-15 18:10:25 INFO  TestListener:42 - suite result size: 0
18:10:25.923 [QUIET] [system.out] 18:10:25.922 [QUIET] [system.out] 2015-06-15 18:10:25 INFO  TestListener:24 - ========> fail test: test1
18:10:25.924 [QUIET] [system.out] 18:10:25.923 [QUIET] [system.out] 2015-06-15 18:10:25 INFO      TestListener:25 - ========> fail test method name: test1
18:10:25.924 [QUIET] [system.out] 18:10:25.924 [QUIET] [system.out] 2015-06-15 18:10:25 INFO  TestListener:40 - fail test count: 0
18:10:25.925 [QUIET] [system.out] 18:10:25.925 [QUIET] [system.out] 2015-06-15 18:10:25 INFO  TestListener:41 - pass test count: 1
18:10:25.926 [QUIET] [system.out] 18:10:25.926 [QUIET] [system.out] 2015-06-15 18:10:25 INFO  TestListener:42 - suite result size: 0
18:10:25.942 [QUIET] [system.out] 18:10:25.941 [QUIET] [system.out] 2015-06-15 18:10:25 INFO  TestListener:17 - =======> inside TestListener.onFinish
18:10:25.945 [QUIET] [system.out] 18:10:25.944 [QUIET] [system.out] 2015-06-15 18:10:25 INFO      TestListener:40 - fail test count: 0
18:10:25.948 [QUIET] [system.out] 18:10:25.947
18:10:25.950 [DEBUG] [TestEventLogger] 
18:10:25.950 [DEBUG] [TestEventLogger] retry tests > com.trulia.regression.tests.retrytests.RetryTest.test1 FAILED
18:10:25.951 [DEBUG] [TestEventLogger]     java.lang.AssertionError: null
18:10:25.951 [DEBUG] [TestEventLogger]         at org.testng.Assert.fail(Assert.java:94)
18:10:25.951 [DEBUG] [TestEventLogger]         at org.testng.Assert.fail(Assert.java:101)
18:10:25.951 [QUIET] [system.out]  [
18:10:25.951 [DEBUG] [TestEventLogger]         at com.trulia.regression.tests.retrytests.RetryTest.test1(RetryTest.java:27)
18:10:25.952 [DEBUG] [TestEventLogger]         at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
18:10:25.952 [DEBUG] [TestEventLogger]         at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
18:10:25.952 [DEBUG] [TestEventLogger]         at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
18:10:25.952 [DEBUG] [TestEventLogger]         at java.lang.reflect.Method.invoke(Method.java:606)
18:10:25.952 [DEBUG] [TestEventLogger]         at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:84)
18:10:25.952 [DEBUG] [TestEventLogger]         at org.testng.internal.Invoker.invokeMethod(Invoker.java:714)
18:10:25.953 [DEBUG] [TestEventLogger]         at org.testng.internal.Invoker.invokeTestMethod(Invoker.java:901)
18:10:25.953 [DEBUG] [TestEventLogger]         at org.testng.internal.Invoker.invokeTestMethods(Invoker.java:1231)
18:10:25.953 [DEBUG] [TestEventLogger]         at org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:127)
18:10:25.953 [DEBUG] [TestEventLogger]         at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:111)
18:10:25.953 [DEBUG] [TestEventLogger]         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
18:10:25.953 [DEBUG] [TestEventLogger]         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
18:10:25.953 [DEBUG] [TestEventLogger]         at java.lang.Thread.run(Thread.java:745)
18:10:25.955 [DEBUG] [TestEventLogger] 
18:10:25.956 [DEBUG] [TestEventLogger] retry tests > com.trulia.regression.tests.retrytests.RetryTest.test1 STARTED
18:10:25.957 [DEBUG] [TestEventLogger] 
18:10:25.957 [DEBUG] [TestEventLogger] retry tests > com.trulia.regression.tests.retrytests.RetryTest.test1 PASSED
18:10:25.957 [DEBUG] [TestEventLogger] 
18:10:25.957 [DEBUG] [TestEventLogger] retry tests FAILED
18:10:25.958 [QUIET] [system.out] QUIET] [system.out] 2015-06-15 18:10:25 INFO  TestListener:41 - pass test count: 1
18:10:25.959 [QUIET] [system.out] 18:10:25.959 [QUIET] [system.out] 2015-06-15 18:10:25 INFO  TestListener:42 - suite result size: 0
18:10:26.056 [QUIET] [system.out] 18:10:26.056
18:10:26.056 [DEBUG] [TestEventLogger] 
18:10:26.056 [QUIET] [system.out]  [INFO] [org.gradle.api.internal.tasks.testing.worker.TestWorker] Gradle Test Executor 1 finished executing tests.
18:10:26.056 [DEBUG] [TestEventLogger] Gradle Test Executor 1 FAILED
18:10:26.056 [QUIET] [system.out] 
18:10:26.059 [QUIET] [system.out] 18:10:26.059 [DEBUG] [org.gradle.process.internal.child.ActionExecutionWorker] Completed Gradle Test Executor 1.
18:10:26.064 [QUIET] [system.out] 18:10:26.064 [DEBUG] [org.gradle.process.internal.child.ActionExecutionWorker] Stopping client connection.
18:10:26.092 [DEBUG] [org.gradle.process.internal.DefaultExecHandle] Changing state to: SUCCEEDED
18:10:26.092 [DEBUG] [org.gradle.process.internal.DefaultExecHandle] Process 'Gradle Test Executor 1' finished with exit value 0 (state: SUCCEEDED)
18:10:26.095 [DEBUG] [TestEventLogger] 
18:10:26.095 [DEBUG] [TestEventLogger] Test Run FAILED
18:10:26.096 [ERROR] [org.gradle.api.internal.tasks.testing.logging.TestCountLogger] 
2 tests completed, 1 failed
18:10:26.116 [INFO] [org.gradle.api.internal.tasks.testing.junit.result.Binary2JUnitXmlReportGenerator] Finished generating test XML results (0.007 secs) into: /Users/hyeung/workspace/test-automation/testruns/consumer_funnel/smoke/testng-retry.xml/reports
18:10:26.117 [INFO] [org.gradle.api.internal.tasks.testing.junit.report.DefaultTestReport] Generating HTML test report...
18:10:26.141 [INFO] [org.gradle.api.internal.tasks.testing.junit.report.DefaultTestReport] Finished generating test html results (0.024 secs) into: /Users/hyeung/workspace/test-automation/testruns/consumer_funnel/smoke/testng-retry.xml/reports
18:10:26.142 [DEBUG] [org.gradle.api.internal.tasks.execution.ExecuteAtMostOnceTaskExecuter] Finished executing task ':test'
18:10:26.143 [LIFECYCLE] [class org.gradle.TaskExecutionLogger] :test FAILED
18:10:26.143 [INFO] [org.gradle.execution.taskgraph.AbstractTaskPlanExecutor] :test (Thread[main,5,main]) completed. Took 3.606 secs.
18:10:26.143 [DEBUG] [org.gradle.execution.taskgraph.AbstractTaskPlanExecutor] Task worker [Thread[main,5,main]] finished, busy: 9.255 secs, idle: 0.007 secs
18:10:26.149 [ERROR] [org.gradle.BuildExceptionReporter] 
18:10:26.150 [ERROR] [org.gradle.BuildExceptionReporter] FAILURE: Build failed with an exception.
18:10:26.150 [ERROR] [org.gradle.BuildExceptionReporter] 
18:10:26.151 [ERROR] [org.gradle.BuildExceptionReporter] * What went wrong:
18:10:26.151 [ERROR] [org.gradle.BuildExceptionReporter] Execution failed for task ':test'.
18:10:26.151 [ERROR] [org.gradle.BuildExceptionReporter] > There were failing tests. See the report at: file:///Users/hyeung/workspace/test-automation/testruns/consumer_funnel/smoke/testng-retry.xml/reports/index.html
18:10:26.152 [ERROR] [org.gradle.BuildExceptionReporter] 
18:10:26.152 [ERROR] [org.gradle.BuildExceptionReporter] * Try:
18:10:26.152 [ERROR] [org.gradle.BuildExceptionReporter] Run with --stacktrace option to get the stack trace. 
18:10:26.153 [LIFECYCLE] [org.gradle.BuildResultLogger] 
18:10:26.153 [LIFECYCLE] [org.gradle.BuildResultLogger] BUILD FAILED
18:10:26.153 [LIFECYCLE] [org.gradle.BuildResultLogger] 
18:10:26.153 [LIFECYCLE] [org.gradle.BuildResultLogger] Total time: 12.365 sec

Here’s how my gradle file test section looks like:

test {

testClassesDir(new File("build/classes/main"))
resultDir = new File("$buildDir/testruns/$fileName/reports")
resultDir.mkdirs()
getReports().getJunitXml().setDestination(resultDir)
getReports().getHtml().setDestination(resultDir)
println "==============> resultDir: " + getReports().getJunitXml().getDestination()
getTestListenerBroadcaster().eachWithIndex { item, index ->
    println "looping listeners..."
    println item.getClass()
    println index
}

systemProperty 'test_site_env', testSiteEnv
systemProperty 'run_code_coverage', runCodeCoverage
systemProperty 'tunnel_identifier', tunnelIdentifier
test.testLogging.showStandardStreams = true

useTestNG() {
    suites "$buildDir/testFarmTestngConfig/$fileName"
    useDefaultListeners(false)
    outputDirectory = resultDir
}

def testOptions = options {
    listeners.add("com.trulia.infrastructure.TestListener") //this is our custom test listener
}

//listeners = getTestListenerBroadcaster()

outputs.upToDateWhen {
    false
}
test {
    jvmArgs '-Xmx1024m', '-XX:MaxPermSize=512m', '-XX:+HeapDumpOnOutOfMemoryError', '-XX:+UseMembar'
}
}

It looks like gradle has it’s own test event listen and whatever I pass in thru the gradle options got ignored.

2

Hi Hinling,
Have you found any solution for this issue? I am also facing same issue but could not find any alternatives.

Thanks

3

Hi,

I am facing a similar issue when using the Spock-Framework for integration tests. If I run the single test everything works fine, but when executing the conplete set the captured System.out is wrong.
It also looks that some later test are not even executed.

Any idea is appreciated.

4

Remember the build.gradle file is a Groovy program. You can store the number of times a test was retried using the afterTest hook and then subtract this value from Gradle’s test counters when your suite is complete.