Reproduce with should include -Dtests.iters=N [LUCENE-6194]

[asfimport]

I was playing with the patch on #7128, and hit a test failure, but then the "Reproduce with: " failed to reproduce, which threw me for a bit of a loop, until I realized it was missing the -Dtests.iters=N.

To see this, apply the patch on #7128 to trunk and then run this:

ant test  -Dtestcase=TestPriorityQueue -Dtests.method=testRemovalsAndInsertions* -Dtests.seed=2576D26D551748E5 -Dtests.slow=true -Dtests.linedocsfile=/lucenedata/hudson.enwiki.random.lines.txt -Dtests.locale=ru_RU -Dtests.timezone=Europe/Paris -Dtests.asserts=true -Dtests.file.encoding=UTF-8 -Dtests.iters=10

(or just insert a random test failure into e.g. TestDemo or something).

It should fail, but the "Reproduce with: ..." line does not include -Dtests.iters=10. I think it should?

---

Migrated from LUCENE-6194 by Michael McCandless (@mikemccand), updated Jan 23 2015

[asfimport]

Dawid Weiss (@dweiss) (migrated from JIRA)

If reiterations are independent then the failure reproduce-with message should point you at the failing iteration, without the need to loop through any previous seeds... At least in an ideal world this should be the case?

[asfimport]

Michael McCandless (@mikemccand) (migrated from JIRA)

At least in an ideal world this should be the case?

I agree, hrmph. Here's the failure I see:

   [junit4]   2> NOTE: download the large Jenkins line-docs file by running 'ant get-jenkins-line-docs' in the lucene directory.
   [junit4]   2> NOTE: reproduce with: ant test  -Dtestcase=TestPriorityQueue -Dtests.method=testRemovalsAndInsertions -Dtests.seed=2576D26D551748E5 -Dtests.slow=true -Dtests.linedocsfile=/lucenedata/hudson.enwiki.random.lines.txt -Dtests.locale=ru_RU -Dtests.timezone=Europe/Paris -Dtests.asserts=true -Dtests.file.encoding=UTF-8
   [junit4] FAILURE 0.13s | TestPriorityQueue.testRemovalsAndInsertions <<<
   [junit4]    > Throwable #1: java.lang.AssertionError: parent=69258832 child=69258832
   [junit4]    > 	at __randomizedtesting.SeedInfo.seed([2576D26D551748E5:379377B96F92B34E]:0)
   [junit4]    > 	at org.apache.lucene.util.TestPriorityQueue$IntegerQueue.checkValidity(TestPriorityQueue.java:41)
   [junit4]    > 	at org.apache.lucene.util.TestPriorityQueue.testRemovalsAndInsertions(TestPriorityQueue.java:171)
   [junit4]    > 	at java.lang.Thread.run(Thread.java:745)

I think the bug is that the 2nd part of the seed is not included in the repro line? Because if I use that seed instead, i.e.:

ant test  -Dtestcase=TestPriorityQueue -Dtests.method=testRemovalsAndInsertions* -Dtests.seed=2576D26D551748E5:379377B96F92B34E -Dtests.slow=true -Dtests.linedocsfile=/lucenedata/hudson.enwiki.random.lines.txt -Dtests.locale=ru_RU -Dtests.timezone=Europe/Paris -Dtests.asserts=true -Dtests.file.encoding=UTF-8

THEN the failure does reproduce with only 1 iteration.

[asfimport]

Dawid Weiss (@dweiss) (migrated from JIRA)

Yes, this is correct behavior. The "second" part of the seed is derived from (the first part + iteration number). Note, however, that if you provide both parts and run multiple iterations then all of the iterations will be repeated with exactly the same randomness.

This behavior is useful to detect non-deterministic tests. Note the difference – if your test fails some iterations with:

-Dtests.seed=dead -Dtests.iters=100

it means for "certain" seeds (at certain iterations) the code is failing, while if your test case fails intermittently on:

-Dtests.seed=dead:beef -Dtests.iters=100

then there is something non-related to the randomness that is causing the failure for a particular seed (dead:beef).

Technically the first segment applies to static context (randomness) and the second segment applies to any instance-level context (randomness).

[asfimport]

Michael McCandless (@mikemccand) (migrated from JIRA)

Thanks for the explanation Dawid.

But if it's the correct behavior, why does the "Reproduce with: " not in fact reproduce the failure? Somewhere something somehow seems wrong :)

I don't see any non-determinism in the test (no threads involved, random() is alway used, etc.).

It seems like either we need the -Dtests.iters=100 in the repro line, or, the repro line should include the "per-iter seed" so it does in fact reproduce...

[asfimport]

Dawid Weiss (@dweiss) (migrated from JIRA)

Well, I guess that's what I was trying to say – some understanding of how it works should be present, there is no single "reproduce with" set of steps, at least if you want to really get to the bottom of the problem.

The "safer" bet for "reproduce with" would be to emit the master seed and -Dtests.iters=X if X>1. The full seed will be typically present in stack traces and all other messages anyway, so it can be always typed-in explicitly.

[asfimport]

Michael McCandless (@mikemccand) (migrated from JIRA)

Can we just add the 2nd part of the seed when test.iters > 1? That's a more efficient "repro" than putting only the master seed in and adding -Dtests.iters=N?

[asfimport]

Dawid Weiss (@dweiss) (migrated from JIRA)

You could, but if a given test does have iteration-related dependencies (for example leaks memory and only fails after N iterations) then you would have a misleading message as well... There is no "right" scenario to cover all possible situations I think. The understanding of what these "components" of the random seed are (in correlation with test reiterations) is crucial; no single "reproduce with" message is going to be helpful in all situations.

The best way to signal an error would be to display this...

test seed: x:y
test iterations: z
see explanation of how randomization and repeated tests work: [here]

Another way to say it is that you can change the message any way you like, in the end somebody will be confused by the "reproduce with" message. :)

[asfimport]

Ryan Ernst (@rjernst) (migrated from JIRA)

While there might not be one single "right" reproduce message, there are certainly ones that are better than others? What we have now doesn't seem to work, since the reproduce line will currently only run the first iteration if there were multiple. Could we output both repro lines, the first one with the child seed, and the second with -Dtests.iters?

[asfimport]

Dawid Weiss (@dweiss) (migrated from JIRA)

Up to you, really. To me full seed + the number of iterations is sufficient, but I have an understanding of what each of these component does.

[asfimport]

Chris M. Hostetter (@hossman) (migrated from JIRA)

Note, however, that if you provide both parts and run multiple iterations then all of the iterations will be repeated with exactly the same randomness.

yes, but then it would be doing exactly what you asked it too - it's doing many iterations with both a fixed master seed and a fixed iteration seed.

This behavior is useful to detect non-deterministic tests. Note the difference – if your test fails some iterations with:

-Dtests.seed=dead -Dtests.iters=100

it means for "certain" seeds (at certain iterations) the code is failing, while if your test case fails intermittently on:

-Dtests.seed=dead:beef -Dtests.iters=100

then there is something non-related to the randomness that is causing the failure for a particular seed (dead:beef).

...i think the best course of action is to assume the test is deterministic, and include the full seed since that's the fastest way to "reproduce" a failure in code that was triggered by the randomly generated "input"

if it doesn't reproduce, then the user (who must already be relatively familiar with teh test framework if he was even trying test.iters in hte first place) will have a good indication that hte test is flawed.

—

to me, including the full seed seems like th best course of action for hte reproduce line, in particular because of how the reproduce lines (plural) are reported when you use test.iters in the first place.

consider this diff...

Index: core/src/test/org/apache/lucene/TestSearch.java
===================================================================
--- core/src/test/org/apache/lucene/TestSearch.java	(revision 1654092)
+++ core/src/test/org/apache/lucene/TestSearch.java	(working copy)
`@@` -34,6 +34,11 `@@`
 /** JUnit adaptation of an older test case SearchTest. */
 public class TestSearch extends LuceneTestCase {
 
+  public void testReproduceLine() throws Exception { // nocommit
+    assertTrue(0 < random().nextInt(100)); // will fail on '0'
+  }
+
+
   public void testNegativeQueryBoost() throws Exception {
     Query q = new TermQuery(new Term("foo", "bar"));
     q.setBoost(-42f);

...and this output...

hossman@frisbee:\~/lucene/dev/lucene/core$ ant test -Dtestcase=TestSearch -Dtests.method=testReproduceLine\* -Dtests.iters=500
Buildfile: /home/hossman/lucene/dev/lucene/core/build.xml

   [junit4] <JUnit4> says שלום! Master seed: 6DAA9E4F7FABD6FC
   [junit4] Executing 1 suite with 1 JVM.
   [junit4] 
   [junit4] Started J0 PID(16679@frisbee).
   [junit4] Suite: org.apache.lucene.TestSearch
   [junit4] OK      0.08s | TestSearch.testReproduceLine {#0 seed=[6DAA9E4F7FABD6FC:F8FFD9389F6A3705]}
   [junit4] OK      0.00s | TestSearch.testReproduceLine {#1 seed=[6DAA9E4F7FABD6FC:4CA965C4ABA8FC29]}
   [junit4] OK      0.01s | TestSearch.testReproduceLine {#2 seed=[6DAA9E4F7FABD6FC:C240F318FA6CB4E2]}
   [junit4] OK      0.01s | TestSearch.testReproduceLine {#3 seed=[6DAA9E4F7FABD6FC:F3AE58FD9692EFCB]}
   [junit4] OK      0.00s | TestSearch.testReproduceLine {#4 seed=[6DAA9E4F7FABD6FC:BF6FDD50379A2F70]}
   [junit4] OK      0.01s | TestSearch.testReproduceLine {#5 seed=[6DAA9E4F7FABD6FC:2E950E0F4A266270]}
...
   [junit4] OK      0.01s | TestSearch.testReproduceLine {#190 seed=[6DAA9E4F7FABD6FC:245CC0506485B2F4]}
   [junit4] OK      0.01s | TestSearch.testReproduceLine {#191 seed=[6DAA9E4F7FABD6FC:A72F9FDAAB585D2E]}
   [junit4]   2> NOTE: reproduce with: ant test  -Dtestcase=TestSearch -Dtests.method=testReproduceLine -Dtests.seed=6DAA9E4F7FABD6FC -Dtests.slow=true -Dtests.locale=lt_LT -Dtests.timezone=America/Cuiaba -Dtests.asserts=true -Dtests.file.encoding=UTF-8
   [junit4] FAILURE 0.14s | TestSearch.testReproduceLine {#192 seed=[6DAA9E4F7FABD6FC:E53D5B74EA5CDF58]} <<<
   [junit4]    > Throwable #1: java.lang.AssertionError
   [junit4]    > 	at __randomizedtesting.SeedInfo.seed([6DAA9E4F7FABD6FC:E53D5B74EA5CDF58]:0)
   [junit4]    > 	at org.apache.lucene.TestSearch.testReproduceLine(TestSearch.java:38)
   [junit4]    > 	at java.lang.Thread.run(Thread.java:745)
   [junit4] OK      0.00s | TestSearch.testReproduceLine {#193 seed=[6DAA9E4F7FABD6FC:B1832CB6030655C9]}
...
   [junit4] OK      0.00s | TestSearch.testReproduceLine {#225 seed=[6DAA9E4F7FABD6FC:676822DBF04739BE]}
   [junit4]   2> NOTE: reproduce with: ant test  -Dtestcase=TestSearch -Dtests.method=testReproduceLine -Dtests.seed=6DAA9E4F7FABD6FC -Dtests.slow=true -Dtests.locale=lt_LT -Dtests.timezone=America/Cuiaba -Dtests.asserts=true -Dtests.file.encoding=UTF-8
   [junit4] FAILURE 0.01s | TestSearch.testReproduceLine {#226 seed=[6DAA9E4F7FABD6FC:1C72A218C788A63A]} <<<
   [junit4]    > Throwable #1: java.lang.AssertionError
   [junit4]    > 	at __randomizedtesting.SeedInfo.seed([6DAA9E4F7FABD6FC:1C72A218C788A63A]:0)
   [junit4]    > 	at org.apache.lucene.TestSearch.testReproduceLine(TestSearch.java:38)
   [junit4]    > 	at java.lang.Thread.run(Thread.java:745)
   [junit4] OK      0.00s | TestSearch.testReproduceLine {#227 seed=[6DAA9E4F7FABD6FC:E7C00D558B908387]}
...
   [junit4] OK      0.00s | TestSearch.testReproduceLine {#311 seed=[6DAA9E4F7FABD6FC:4A8C6A00C2513040]}
   [junit4]   2> NOTE: reproduce with: ant test  -Dtestcase=TestSearch -Dtests.method=testReproduceLine -Dtests.seed=6DAA9E4F7FABD6FC -Dtests.slow=true -Dtests.locale=lt_LT -Dtests.timezone=America/Cuiaba -Dtests.asserts=true -Dtests.file.encoding=UTF-8
   [junit4] FAILURE 0.02s | TestSearch.testReproduceLine {#312 seed=[6DAA9E4F7FABD6FC:4357B0D76C4DC156]} <<<
   [junit4]    > Throwable #1: java.lang.AssertionError
   [junit4]    > 	at __randomizedtesting.SeedInfo.seed([6DAA9E4F7FABD6FC:4357B0D76C4DC156]:0)
   [junit4]    > 	at org.apache.lucene.TestSearch.testReproduceLine(TestSearch.java:38)
   [junit4]    > 	at java.lang.Thread.run(Thread.java:745)
   [junit4] OK      0.00s | TestSearch.testReproduceLine {#313 seed=[6DAA9E4F7FABD6FC:427ED3795B660F]}
...

...what's the point of including the reproduce line for every individual failure if they are all identicle and don't actually include enough context to reproduce? Adding Dtests.iters=N to the reproduce line seems like it would be a lot less helpful then adding the full seed so that i have several individual commands to try and reproduce - and as long as those several commands reproduce reliably, i can post then in jira/email for diagnosing the problem with the code ... if they don't reproduce, then my original execuction line with -Dtests.iters=N is going to be very useful for getting to the bottom of how/why the test is broken

[asfimport]

Ryan Ernst (@rjernst) (migrated from JIRA)

+1 to what hoss said. That is a good point about how spitting back out the original line multiple times seems kind of silly in context.

[asfimport]

Robert Muir (@rmuir) (migrated from JIRA)

Can we just remove tests.iters already now that we have 'ant beast'?

tests.iters is a huge trap trap, someone runs it with n=10000 then commits their code and wonders why jenkins fails. The reason is, our test framework includes a lot of class-level randomness and when you use test.iters it does not exhaust those possibilities. This makes it useless.

On the other hand 'ant beast' is the same thing as actually running the test many times and you can be confident that it is able to explore the entire search space. We've also done work to make it nicer and more friendly, e.g. setting better junit4 options for 'beast' so it only includes relevant output and minimal noise for each iteration.

You can beast with tests.verbose and everything works as you expect.

For seeds that don't reproduce well, you can pass -Dtests.dups to ant beast and hammer the problematic seed with multiple threads. (it currently gives an annoying warning from junit for every iteration that am i currently unable to remove since i dont know how to set the ignore, but it works (separate issue): "junit4 Duplicate suite name used with XML reports: org.apache.lucene.TestDemo. This may confuse tools that process XML reports. Set 'ignoreDuplicateSuites' to true to skip this message."

So yeah, please, kill tests.iters :)

[asfimport]

Dawid Weiss (@dweiss) (migrated from JIRA)

Good points, Hoss.

> This makes it useless

This is true for Lucene which indeed does use a lot of static-level randomness. In general static fixtures are a not such a great idea because they are effectively reused across different tests... Lucene only uses this because it speeds up tests.

> Set 'ignoreDuplicateSuites' to true to skip this message

It tells you exactly what to do :)

                <!-- ANT-compatible XMLs for jenkins records etc. -->
-                <junit4:report-ant-xml dir="@{junit.output.dir}" outputStreams="no" />
+                <junit4:report-ant-xml dir="@{junit.output.dir}" outputStreams="no" ignoreDuplicateSuites="true" />

[asfimport]

Robert Muir (@rmuir) (migrated from JIRA)

This is true for Lucene which indeed does use a lot of static-level randomness. In general static fixtures are a not such a great idea because they are effectively reused across different tests... Lucene only uses this because it speeds up tests.

Right but this is lucene we are talking about :) So I think we should remove tests.iters and just simplify the whole situation.

Again: my problem is the trap. Whenever i see people using this, i know they will cause jenkins build failures.

It tells you exactly what to do

Thanks, I did try this. I wasnt able to silence this thing, will try it again...

[asfimport]

Dawid Weiss (@dweiss) (migrated from JIRA)

> Thanks, I did try this. I wasnt able to silence this thing, will try it again...

Perhaps you've added it to junit4 task; it needs to go to the reporter node (because they're fairly independent components).