Lucene - Core
  1. Lucene - Core
  2. LUCENE-5622

Fail tests if they print over the given limit of bytes to System.out or System.err

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: 4.9, 6.0
    • Component/s: None
    • Labels:
      None
    • Lucene Fields:
      New

      Description

      Some tests print so much stuff they are now undebuggable (see LUCENE-5612).

      From now on, when tests.verbose is false, the number of bytes printed to standard output and error streams will be accounted for and if it exceeds a given limit an assertion will be thrown. The limit is adjustable per-suite using Limit annotation, with the default of 8kb per suite. The check can be suppressed entirely by specifying SuppressSysoutChecks.

      1. LUCENE-5622.patch
        34 kB
        Dawid Weiss
      2. LUCENE-5622.patch
        15 kB
        Dawid Weiss
      3. LUCENE-5622.patch
        20 kB
        Robert Muir
      4. LUCENE-5622.patch
        13 kB
        Dawid Weiss
      5. LUCENE-5622.patch
        4 kB
        Robert Muir

        Activity

        Hide
        Robert Muir added a comment -

        Here's a prototype.

        Show
        Robert Muir added a comment - Here's a prototype.
        Hide
        Michael McCandless added a comment -

        +1, debuggability of tests is important.

        Show
        Michael McCandless added a comment - +1, debuggability of tests is important.
        Hide
        Dawid Weiss added a comment -

        > I think its bad that the testrunner hides this stuff,

        It technically does not. The report which prints stuff to the console does, but that's a different thing from the runner itself. Also, full content of sysouts/ syserrs is dumped (by another report) to disk. See common-build.xml and all junit4:report-* blocks.

        We could just change

         showOutput="${tests.showOutput}"
        

        to true and this would bring all the output back to the console. The problem is (and was) Solr tests, which print humongous outputs.

        Show
        Dawid Weiss added a comment - > I think its bad that the testrunner hides this stuff, It technically does not. The report which prints stuff to the console does, but that's a different thing from the runner itself. Also, full content of sysouts/ syserrs is dumped (by another report) to disk. See common-build.xml and all junit4:report-* blocks. We could just change showOutput= "${tests.showOutput}" to true and this would bring all the output back to the console. The problem is (and was) Solr tests, which print humongous outputs.
        Hide
        Robert Muir added a comment -

        I know solr tests have humungous outputs, but thats not a problem I'm trying to tackle here (they can just override and set NOISY = true always???)

        In this case its just a matter of fixing lucene tests like TestIndexWriter to be more debuggable. So to fix that i want to remove the leniency...

        Show
        Robert Muir added a comment - I know solr tests have humungous outputs, but thats not a problem I'm trying to tackle here (they can just override and set NOISY = true always???) In this case its just a matter of fixing lucene tests like TestIndexWriter to be more debuggable. So to fix that i want to remove the leniency...
        Hide
        Dawid Weiss added a comment -

        Aside from my previous comment, I don't like the way sysout/ syserr is restored inside the stream. If you only mean to detect whether anything was printed, you should delegate writes to original streams, but not restore until the after method is invoked, much like you already do.

        I don't see the point of restoring original streams inside write.

        Show
        Dawid Weiss added a comment - Aside from my previous comment, I don't like the way sysout/ syserr is restored inside the stream. If you only mean to detect whether anything was printed, you should delegate writes to original streams, but not restore until the after method is invoked, much like you already do. I don't see the point of restoring original streams inside write.
        Hide
        Robert Muir added a comment -

        Well we can remove that? I dont care? As long as they fail the test. Like i said its a prototype.

        The one thing this patch does (whether oyu like the details of how this is accomplished or not), is fail the test and remove the leniency

        Show
        Robert Muir added a comment - Well we can remove that? I dont care? As long as they fail the test. Like i said its a prototype. The one thing this patch does (whether oyu like the details of how this is accomplished or not), is fail the test and remove the leniency
        Hide
        Dawid Weiss added a comment -

        Sure. I would do it in a slightly different way though – provide delegate syserr/sysout instances (which always correctly delegate to original streams), get a stack trace of the first call to any write[] methods, mark the test as a failure, but fail it inside the after method (with the captured call stack, which may be useful to debug the sysout). The reason for this is to allow the test to run normally and fail it at the end. Throwing a runtime exception from inside sysout/syserr may result in odd behavior (and may be caught, whereas my suggestion cannot be intercepted by the test code).

        Show
        Dawid Weiss added a comment - Sure. I would do it in a slightly different way though – provide delegate syserr/sysout instances (which always correctly delegate to original streams), get a stack trace of the first call to any write[] methods, mark the test as a failure, but fail it inside the after method (with the captured call stack, which may be useful to debug the sysout). The reason for this is to allow the test to run normally and fail it at the end. Throwing a runtime exception from inside sysout/syserr may result in odd behavior (and may be caught, whereas my suggestion cannot be intercepted by the test code).
        Hide
        Dawid Weiss added a comment -

        By odd behavior I include sysouts from non-main test thread...

        Show
        Dawid Weiss added a comment - By odd behavior I include sysouts from non-main test thread...
        Hide
        Robert Muir added a comment -

        Which is exactly what happens in TestIndexWriter Good idea. I like it.

        is it ok to fail in that TestRuleSetUpAndRestoreClassEnv.after(), e.g. will the exc be delivered etc?? that part wasnt clear to me since nothing does that. thats why i did it the current hacky way (without doing experiments)

        Show
        Robert Muir added a comment - Which is exactly what happens in TestIndexWriter Good idea. I like it. is it ok to fail in that TestRuleSetUpAndRestoreClassEnv.after(), e.g. will the exc be delivered etc?? that part wasnt clear to me since nothing does that. thats why i did it the current hacky way (without doing experiments)
        Hide
        Dawid Weiss added a comment -

        You know what... I'm not sure. How about if you assign it to me and I'll look into it later on, ok?

        Show
        Dawid Weiss added a comment - You know what... I'm not sure. How about if you assign it to me and I'll look into it later on, ok?
        Hide
        Dawid Weiss added a comment -

        This was trickier than I initially thought because you need to take into account infrastructure which also prints to system streams.

        Anyway, this is the proposed patch. Some tests (in Lucene) don't pass:

        [junit4] - org.apache.lucene.index.TestBackwardsCompatibility (suite)
        [junit4] - org.apache.lucene.index.TestCrash (suite)
        [junit4] - org.apache.lucene.index.TestIndexWriter (suite)
        [junit4] - org.apache.lucene.index.TestDocValuesIndexing (suite)

        I didn't check Solr at all, but I suspect we need to put suppression of this rule on the base class because Solr tests print logs to console.

        Show
        Dawid Weiss added a comment - This was trickier than I initially thought because you need to take into account infrastructure which also prints to system streams. Anyway, this is the proposed patch. Some tests (in Lucene) don't pass: [junit4] - org.apache.lucene.index.TestBackwardsCompatibility (suite) [junit4] - org.apache.lucene.index.TestCrash (suite) [junit4] - org.apache.lucene.index.TestIndexWriter (suite) [junit4] - org.apache.lucene.index.TestDocValuesIndexing (suite) I didn't check Solr at all, but I suspect we need to put suppression of this rule on the base class because Solr tests print logs to console.
        Hide
        Dawid Weiss added a comment -

        I see that some of these are randomized, the seed I used was 4BCBDFFC4832769F.

          private static IndexUpgrader newIndexUpgrader(Directory dir) {
            final boolean streamType = random().nextBoolean();
        ...
              case 1: return new IndexUpgrader(dir, TEST_VERSION_CURRENT, 
                                               streamType ? null : System.err, false);
        

        Don't know what it does or why it's needed – Robert, could you address the failing test cases?

        Show
        Dawid Weiss added a comment - I see that some of these are randomized, the seed I used was 4BCBDFFC4832769F. private static IndexUpgrader newIndexUpgrader(Directory dir) { final boolean streamType = random().nextBoolean(); ... case 1: return new IndexUpgrader(dir, TEST_VERSION_CURRENT, streamType ? null : System .err, false ); Don't know what it does or why it's needed – Robert, could you address the failing test cases?
        Hide
        Robert Muir added a comment -

        Done.

        THere are problems with the fancy nested tests:

           [junit4] Tests with failures:
           [junit4]   - org.apache.lucene.util.junitcompat.TestExceptionInBeforeClassHooks.testExceptionWithinTestFailsTheTest
           [junit4]   - org.apache.lucene.util.junitcompat.TestExceptionInBeforeClassHooks.testExceptionWithinBefore
           [junit4]   - org.apache.lucene.util.junitcompat.TestExceptionInBeforeClassHooks.testExceptionInBeforeClassFailsTheTest
           [junit4]   - org.apache.lucene.util.junitcompat.TestSeedFromUncaught.testUncaughtDumpsSeed
        

        Also, I think we should allow output when a sysprop (tests.noisy?) is set. This is important to automatically add when using -Dtestcase, some developers like to debug with SOP. Often times its the case where you need to use a shell-script to beast a test, etc. So these workflows will still work, we just want to fail when running the whole suite.

        Show
        Robert Muir added a comment - Done. THere are problems with the fancy nested tests: [junit4] Tests with failures: [junit4] - org.apache.lucene.util.junitcompat.TestExceptionInBeforeClassHooks.testExceptionWithinTestFailsTheTest [junit4] - org.apache.lucene.util.junitcompat.TestExceptionInBeforeClassHooks.testExceptionWithinBefore [junit4] - org.apache.lucene.util.junitcompat.TestExceptionInBeforeClassHooks.testExceptionInBeforeClassFailsTheTest [junit4] - org.apache.lucene.util.junitcompat.TestSeedFromUncaught.testUncaughtDumpsSeed Also, I think we should allow output when a sysprop (tests.noisy?) is set. This is important to automatically add when using -Dtestcase, some developers like to debug with SOP. Often times its the case where you need to use a shell-script to beast a test, etc. So these workflows will still work, we just want to fail when running the whole suite.
        Hide
        Dawid Weiss added a comment -

        I'll look at these.

        > This is important to automatically add when using -Dtestcase, some developers like to debug with SOP.

        Isn't this the purpose of tests.verbose? I agree with what you're saying about SOP and I'm sort of worried that people will hate this feature (and me, indirectly...).

        Show
        Dawid Weiss added a comment - I'll look at these. > This is important to automatically add when using -Dtestcase, some developers like to debug with SOP. Isn't this the purpose of tests.verbose? I agree with what you're saying about SOP and I'm sort of worried that people will hate this feature (and me, indirectly...).
        Hide
        Robert Muir added a comment -

        Maybe you will hate it, but we need it to be practical. tests.verbose is too much, it hides test failures.

        For example if you turned it on, the test in LUCENE-5623 would never fail, because it hides concurrency issues.

        I know you may not like that we have to resort to such shellscripts etc, but I can assure you its necessary

        Show
        Robert Muir added a comment - Maybe you will hate it, but we need it to be practical. tests.verbose is too much, it hides test failures. For example if you turned it on, the test in LUCENE-5623 would never fail, because it hides concurrency issues. I know you may not like that we have to resort to such shellscripts etc, but I can assure you its necessary
        Hide
        ASF subversion and git services added a comment -

        Commit 1589104 from Robert Muir in branch 'dev/trunk'
        [ https://svn.apache.org/r1589104 ]

        LUCENE-5622: fix noisy tests

        Show
        ASF subversion and git services added a comment - Commit 1589104 from Robert Muir in branch 'dev/trunk' [ https://svn.apache.org/r1589104 ] LUCENE-5622 : fix noisy tests
        Hide
        Dawid Weiss added a comment -

        I've added a patch that does not check for sysouts by default – this would be very annoying for people using IDEs. The ant test also doesn't check for these by default (to simplify the build file in case of filtering, etc.). You can turn it on by passing -Dtests.sysouts=no to ant (we could modify jenkins runs to do it, perhaps).

        Again, didn't check Solr at all. There's still something odd going on with those nested tests but they did build over 5 times for me now so we'll see how it goes.

        Show
        Dawid Weiss added a comment - I've added a patch that does not check for sysouts by default – this would be very annoying for people using IDEs. The ant test also doesn't check for these by default (to simplify the build file in case of filtering, etc.). You can turn it on by passing -Dtests.sysouts=no to ant (we could modify jenkins runs to do it, perhaps). Again, didn't check Solr at all. There's still something odd going on with those nested tests but they did build over 5 times for me now so we'll see how it goes.
        Hide
        ASF subversion and git services added a comment -

        Commit 1589111 from Robert Muir in branch 'dev/branches/branch_4x'
        [ https://svn.apache.org/r1589111 ]

        LUCENE-5622: fix noisy tests

        Show
        ASF subversion and git services added a comment - Commit 1589111 from Robert Muir in branch 'dev/branches/branch_4x' [ https://svn.apache.org/r1589111 ] LUCENE-5622 : fix noisy tests
        Hide
        Dawid Weiss added a comment -

        There is something odd going on with those nested tests – they fail sporadically for me (even though they should not). I am looking into it.

        Show
        Dawid Weiss added a comment - There is something odd going on with those nested tests – they fail sporadically for me (even though they should not). I am looking into it.
        Hide
        Dawid Weiss added a comment -

        The problem is with Java loggers (default console handler) which grabs the System.out reference once and for all. This causes tests to be order-dependent and the DelegateStream to be propagated outside a given test's scope.

        I'll think of a way to fix this.

        Show
        Dawid Weiss added a comment - The problem is with Java loggers (default console handler) which grabs the System.out reference once and for all. This causes tests to be order-dependent and the DelegateStream to be propagated outside a given test's scope. I'll think of a way to fix this.
        Hide
        Dawid Weiss added a comment -

        While annotating tests that do sysouts I came to the conclusion that it shouldn't be an "all or nothing" threshold. It should be much like the memory leak detector – some sysouts per suite should be fine (say, 1kb), then it should start failing and suggest to change some of the sysouts to if (VERBOSE) or raise the limit by annotating the suite with a higher threshold.

        This would make sense in that we could enable those checks by default without additional jenkins jobs, special properties, etc. What do you think?

        Show
        Dawid Weiss added a comment - While annotating tests that do sysouts I came to the conclusion that it shouldn't be an "all or nothing" threshold. It should be much like the memory leak detector – some sysouts per suite should be fine (say, 1kb), then it should start failing and suggest to change some of the sysouts to if (VERBOSE) or raise the limit by annotating the suite with a higher threshold. This would make sense in that we could enable those checks by default without additional jenkins jobs, special properties, etc. What do you think?
        Hide
        ASF subversion and git services added a comment -

        Commit 1589645 from Dawid Weiss in branch 'dev/branches/LUCENE-5622'
        [ https://svn.apache.org/r1589645 ]

        Branch for LUCENE-5622

        Show
        ASF subversion and git services added a comment - Commit 1589645 from Dawid Weiss in branch 'dev/branches/ LUCENE-5622 ' [ https://svn.apache.org/r1589645 ] Branch for LUCENE-5622
        Hide
        Robert Muir added a comment -

        +1 to that idea. It at least prevents things from getting out of control, which is the most important.

        Show
        Robert Muir added a comment - +1 to that idea. It at least prevents things from getting out of control, which is the most important.
        Hide
        Dawid Weiss added a comment -

        New patch with an adjustablelimit of bytes written to sysout/ syserr before an assertion is thrown. Disabled the check for Solr tests entirely and a few classes from Lucene as well.

        Show
        Dawid Weiss added a comment - New patch with an adjustablelimit of bytes written to sysout/ syserr before an assertion is thrown. Disabled the check for Solr tests entirely and a few classes from Lucene as well.
        Hide
        ASF subversion and git services added a comment -

        Commit 1591222 from Dawid Weiss in branch 'dev/trunk'
        [ https://svn.apache.org/r1591222 ]

        LUCENE-5622: Fail tests if they print over the given limit of bytes to System.out or System.err

        Show
        ASF subversion and git services added a comment - Commit 1591222 from Dawid Weiss in branch 'dev/trunk' [ https://svn.apache.org/r1591222 ] LUCENE-5622 : Fail tests if they print over the given limit of bytes to System.out or System.err
        Hide
        Dawid Weiss added a comment -

        Committed to trunk. Will let it bake a bit before backporting to 4x

        Show
        Dawid Weiss added a comment - Committed to trunk. Will let it bake a bit before backporting to 4x
        Hide
        ASF subversion and git services added a comment -

        Commit 1591273 from Dawid Weiss in branch 'dev/branches/branch_4x'
        [ https://svn.apache.org/r1591273 ]

        LUCENE-5622: Fail tests if they print over the given limit of bytes to System.out or System.err

        Show
        ASF subversion and git services added a comment - Commit 1591273 from Dawid Weiss in branch 'dev/branches/branch_4x' [ https://svn.apache.org/r1591273 ] LUCENE-5622 : Fail tests if they print over the given limit of bytes to System.out or System.err
        Hide
        ASF subversion and git services added a comment -

        Commit 1591279 from Dawid Weiss in branch 'dev/trunk'
        [ https://svn.apache.org/r1591279 ]

        Follow up cleanups to LUCENE-5622.

        Show
        ASF subversion and git services added a comment - Commit 1591279 from Dawid Weiss in branch 'dev/trunk' [ https://svn.apache.org/r1591279 ] Follow up cleanups to LUCENE-5622 .
        Hide
        Dawid Weiss added a comment -

        http://builds.flonkings.com/job/Lucene-4x-Linux-Java7-64-test-only/21354/consoleText

        It failed in a test, yet still complained about sysout enforcement; shouldn't be the case (if a suite fails, no checking should be done).

          [junit4]   2> NOTE: test params are: codec=Lucene46: {field=PostingsFormat(name=Memory doPackFST= false)}, docValues:{}, sim=RandomSimilarityProvider(queryNorm=false,coord=yes): {field=DFR GL3(800.0)}, locale=sr_RS, timezone=America/Monterrey
           [junit4]   2> NOTE: Linux 3.2.0-26-generic amd64/Oracle Corporation 1.7.0_25 (64-bit)/cpus=8,threads=1,free=246490792,total=260243456
           [junit4]   2> NOTE: All tests run in this JVM: [TestTermVectorsReader, TestSegmentTermEnum, TestConstantScoreQuery, TestNRTThreads, TestSentinelIntSet, TestIsCurrent, TestMockDirectoryWrapper, TestLiveFieldValues, TestLucene41StoredFieldsFormat, TestBlockPostingsFormat2, TestNIOFSDirectory, TestIdentityHashSet, TestDoc, TestLucene3xStoredFieldsFormat, TestDocumentsWriterStallControl, TestPerFieldPostingsFormat, TestLucene45DocValuesFormat, TestAutomatonQuery, TestDocTermOrds, TestPayloadTermQuery, Test2BSortedDocValues, TestFlushByRamOrCountsPolicy, TestReusableStringReader, TestOmitPositions, TestIndexWriterThreadsToSegments]
           [junit4]   2> NOTE: reproduce with: ant test  -Dtestcase=TestIndexWriterThreadsToSegments -Dtests.seed=5373C01FEEF4F0D6 -Dtests.slow=true -Dtests.locale=sr_RS -Dtests.timezone=America/Monterrey -Dtests.file.encoding=UTF-8
           [junit4] ERROR   0.00s J2 | TestIndexWriterThreadsToSegments (suite) <<<
           [junit4]    > Throwable #1: java.lang.AssertionError: The test or suite printed 18316 bytes to stdout and stderr, even though the limit was set to 8192 bytes. Increase the limit with @Limit, ignore it completely with @SuppressSysoutChecks or run with -Dtests.verbose=true
           [junit4]    > 	at __randomizedtesting.SeedInfo.seed([5373C01FEEF4F0D6]:0)
           [junit4]    > 	at java.lang.Thread.run(Thread.java:724)
           [junit4] Completed on J2 in 56.03s, 4 tests, 1 failure, 1 error <<< FAILURES!
        
        Show
        Dawid Weiss added a comment - http://builds.flonkings.com/job/Lucene-4x-Linux-Java7-64-test-only/21354/consoleText It failed in a test, yet still complained about sysout enforcement; shouldn't be the case (if a suite fails, no checking should be done). [junit4] 2> NOTE: test params are: codec=Lucene46: {field=PostingsFormat(name=Memory doPackFST= false )}, docValues:{}, sim=RandomSimilarityProvider(queryNorm= false ,coord=yes): {field=DFR GL3(800.0)}, locale=sr_RS, timezone=America/Monterrey [junit4] 2> NOTE: Linux 3.2.0-26- generic amd64/Oracle Corporation 1.7.0_25 (64-bit)/cpus=8,threads=1,free=246490792,total=260243456 [junit4] 2> NOTE: All tests run in this JVM: [TestTermVectorsReader, TestSegmentTermEnum, TestConstantScoreQuery, TestNRTThreads, TestSentinelIntSet, TestIsCurrent, TestMockDirectoryWrapper, TestLiveFieldValues, TestLucene41StoredFieldsFormat, TestBlockPostingsFormat2, TestNIOFSDirectory, TestIdentityHashSet, TestDoc, TestLucene3xStoredFieldsFormat, TestDocumentsWriterStallControl, TestPerFieldPostingsFormat, TestLucene45DocValuesFormat, TestAutomatonQuery, TestDocTermOrds, TestPayloadTermQuery, Test2BSortedDocValues, TestFlushByRamOrCountsPolicy, TestReusableStringReader, TestOmitPositions, TestIndexWriterThreadsToSegments] [junit4] 2> NOTE: reproduce with: ant test -Dtestcase=TestIndexWriterThreadsToSegments -Dtests.seed=5373C01FEEF4F0D6 -Dtests.slow= true -Dtests.locale=sr_RS -Dtests.timezone=America/Monterrey -Dtests.file.encoding=UTF-8 [junit4] ERROR 0.00s J2 | TestIndexWriterThreadsToSegments (suite) <<< [junit4] > Throwable #1: java.lang.AssertionError: The test or suite printed 18316 bytes to stdout and stderr, even though the limit was set to 8192 bytes. Increase the limit with @Limit, ignore it completely with @SuppressSysoutChecks or run with -Dtests.verbose= true [junit4] > at __randomizedtesting.SeedInfo.seed([5373C01FEEF4F0D6]:0) [junit4] > at java.lang. Thread .run( Thread .java:724) [junit4] Completed on J2 in 56.03s, 4 tests, 1 failure, 1 error <<< FAILURES!
        Hide
        Dawid Weiss added a comment -

        Can't reproduce this, everything seems to work fine.

        Show
        Dawid Weiss added a comment - Can't reproduce this, everything seems to work fine.

          People

          • Assignee:
            Dawid Weiss
            Reporter:
            Robert Muir
          • Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development