buck test --code-coverage prints test results n times

[jiangty-addepar]

Repro steps:

Run buck test [target]:test --no-results-cache --code-coverage on a large module with many tests (using testng).

Result:

Test results get printed many times.

In our case, we ran tests that took 78.4s, and both

[-] PROCESSING BUCK FILES...FINISHED 1.1s
[-] BUILDING...FINISHED 6.8s (250/643 JOBS, 11 UPDATED, 0.0% CACHE HITS)
[-] TESTING...FINISHED 78.4s (0 PASS/0 FAIL)

the test results were printed 26 times.

(We're working on the fact that buck test with testng says "0 PASS/0 FAIL," so don't worry about that right now.)

[bhamiltoncx]

I'll fix the 0 PASS/0 FAIL issue. Can you give a specific example of the output, in a github gist? If you could attach buck-out/log/buck-0.log it'd be nice as well.

[jiangty-addepar]

We'd rather not publicly reveal what tests we're running / our logs; what information in particular are you looking for?

[bhamiltoncx]

Understood, I was just trying to get a bit more information so I could reproduce locally.

I think I might have figured out one way this could happen, but I wanted to confirm in your logs. Can you check in your buck-out/log/buck-0.log to see if you have a line containing the string [error]?

If you see a line with [error] in the logs (say, like the following):

[2015-06-24 13:24:07.430][error][command:7c93f5b0-b149-4917-beb6-7e9308b4ccfa][tid:27][com.google.common.eventbus.EventBus.buck-build-events] Could not dispatch event: com.facebook.buck.event.listener.ChromeTraceBuildListener@2ce8eb00 to public void com.facebook.buck.event.listener.ChromeTraceBuildListener.testStartedEvent(com.facebook.buck.rules.TestSummaryEvent$Started)

it means we tried (and failed, due to a bug I'm fixing) to log an error to the console. Any time this happened, you'd see a visual glitch like the one you're describing.

[jiangty-addepar]

Ah, I do see a line with [error]:

[2015-06-24 16:56:45.780][debug][command:null][tid:852][class com.martiansoftware.nailgun.NGSession] Nail finished.
[2015-06-24 16:56:45.780][error][command:null][tid:852][class com.martiansoftware.nailgun.NGSession] Caught NGExitException, cleaning up session and writing exit command to client.
com.martiansoftware.nailgun.NGExitException: ExitException: status 1
    at com.martiansoftware.nailgun.NGSecurityManager.checkExit(NGSecurityManager.java:56)
    at java.lang.Runtime.exit(Runtime.java:107)
    at java.lang.System.exit(System.java:971)
    at com.facebook.buck.cli.Main.runMainThenExit(Main.java:1059)
    at com.facebook.buck.cli.Main.nailMain(Main.java:1075)
    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:497)
    at com.martiansoftware.nailgun.NGSession.run(NGSession.java:338)

[2015-06-24 16:56:45.780][debug][command:null][tid:852][class com.martiansoftware.nailgun.NGSession] Closing client streams and socket.

[bhamiltoncx]

Interesting. That's not quite the one I would have expected (that's only logged at the very end), but it might be related. I have a few fixes out for review now that I hope will help with this.

[jiangty-addepar]

I did buck run a few more times and did not see the above error message again, so I guess that was a red herring... sorry!

Still, hopefully your fix will help?

[bhamiltoncx]

I just pushed a few fixes which should greatly improve the junit test console output. Please update to 899fcfe50805ecdff15a0a3165ba93effaca3352 or later and let me know if that helps.

[bhamiltoncx]

@jiangty-addepar, any luck?

[jiangty-addepar]

sorry, I was on vacation for a week!

Unfortunately, it's still happening, even after we updated :(

[jiangty-addepar]

for reference, I'm running https://github.com/liuyang-li/buck/commits/88c2b52bfa8672a559a6bac749d5dcd4650041da . I'm fairly sure none of our commits should cause this problem.

[bhamiltoncx]

OK. We don't have any tests using testng, so it's unlikely we'll get to this very soon. I've been hammering on the test runner and I haven't seen this.

[tgummerer]

I think the problem are the System.out.println() statements in TestNGRunner. I experienced similar things when I added such statements for debugging purposes.

I think the following might fix it, but I don't have any TestNG tests around with which I could test it, so I'm not submitting a pull request.

diff --git a/src/com/facebook/buck/junit/TestNGRunner.java b/src/com/facebook/buck/junit/TestNGRunner.java
index b9f149e..3ede20e 100644
--- a/src/com/facebook/buck/junit/TestNGRunner.java
+++ b/src/com/facebook/buck/junit/TestNGRunner.java
@@ -44,9 +44,7 @@ import java.util.List;
 public final class TestNGRunner extends BaseRunner {
   @Override
   public void run() throws Throwable {
-    System.out.println("TestNGRunner started!");
     for (String className : testClassNames) {
-      System.out.println("TestNGRunner handling " + className);
       final Class<?> testClass = Class.forName(className);

       List<TestResult> results;
@@ -60,7 +58,6 @@ public final class TestNGRunner extends BaseRunner {
         TestListener listener = new TestListener(results);
         tester.addListener(new TestListener(results));
         try {
-          System.out.println("TestNGRunner running " + className);
           tester.initializeSuitesAndJarFile();
           tester.runSuitesLocally();
         } catch (Throwable e) {
@@ -79,12 +76,10 @@ public final class TestNGRunner extends BaseRunner {
               ResultType.FAILURE, e,
               "", ""));
         }
-        System.out.println("TestNGRunner tested " + className + ", got " + results.size());
       }

       writeResult(className, results);
     }
-    System.out.println("TestNGRunner done!");
   }

   private XmlSuite createXmlSuite(Class<?> c) {

[sdwilsh]

We've got a sample one at test/com/facebook/buck/java/testdata/missing_test_deps/

[jiangty-addepar]

@tgummerer , in our branch https://github.com/liuyang-li/buck/commit/88c2b52bfa8672a559a6bac749d5dcd4650041da , we've already deleted the System.out.println()s, so I don't think that's the issue :/

[tgummerer]

@jiangty-addepar ah sorry I didn't see that. I also can't reproduce this easily myself with the sample @sdwilsh pointed out, so I won't be looking into this further, as I don't have use for testng myself.

[jiangty-addepar]

@tgummerer thanks for looking into it though!