[GitHub] [daffodil] stevedlawrence commented on a diff in pull request #939: Avoid CI false negatives

["stevedlawrence (via GitHub)" <gi...@apache.org>]

stevedlawrence commented on code in PR #939:
URL: https://github.com/apache/daffodil/pull/939#discussion_r1090681291


##########
daffodil-cli/src/test/scala/org/apache/daffodil/CLI/Util.scala:
##########
@@ -241,33 +241,101 @@ object Util {
     val expect = eb.build()
     val tester = new CLITester(expect, toIn)
 
-    try {
-      testFunc(tester)
-    } finally {
-      threadOrProc match {
-        case Left(thread) => thread.join(timeout * 1000)
-        case Right(process) => process.waitFor(timeout, TimeUnit.SECONDS)
-      }
-      expect.close()
-      toIn.close()
-      fromOut.close()
-      fromErr.close()
+    // run the test function in a new thread. We do this so that we can configure
+    // ExpectIt to have an infinite timeout. This way we can trigger a timeout only
+    // after the has CLI exited, at which point we give the test thread timeout
+    // seconds to finish its tests and interrupt it if it still hasn't finished. This
+    // way if the CLI is slow to start up, ExpectIt won't create a timeout exception
+    // and fail the test. We at least let the CLI finish before doing that
+    val testThread = new TestThread(testFunc, tester, threadOrProc)
+    testThread.start()
+
+    // wait for the CLI process/thread to finish with no timeout--we really
+    // don't know how long the CLI is going to take, but we assume the CLI will
+    // eventually finish. If it doesn't, we'll see the hang and investigate
+    threadOrProc match {
+      case Left(thread) => thread.join()
+      case Right(process) => process.waitFor()
     }
 
+    // now that the CLI has finished, we give the test thread timeout seconds
+    // to finish verifying the output. Hopefully it was doing all the checks in
+    // parallel with the CLI thread so it should be mostly complete and not
+    // need the full timeout
+    testThread.join(timeout * 1000)
+
+    // If the test thread still isn't done, assume it failed and is stuck expecting
+    // something that isn't coming. Interrupt the thread to end it. If it is already
+    // finished, this does nothing.
+    testThread.interrupt()
+
+    // at this point we may need to wait for the test thread to die from the
+    // interrupt. Expect might be doing some cleanup as it handles the interruption
+    while (testThread.isAlive) Thread.sleep(100)

Review Comment:
   > Is this line the place you were talking about where we might hang forever?
   
   This is one potential place. Really the only way for this loop to hang is if the expect library ignores the above interrupt (e.g. catches an `InterruptedException`, ignores it, and continues doing expect stuff). In my development of this stuff, it seems the expect library handles interrupts as expected. And I do see logic in the expect code to make sure it fails expect()s if it has been interrupted.
   
   And now that I think about it, I would actually prefer to change this line to `testThread.join()` to wait until the test thread dies from the interrupt. I think `join` is just implemented as a very similar `isAlive` loop, so this would be cleaner.
   
   Another place things could potentially hang with these changes is in this code above:
   ```scala
      threadOrProc match {
         case Left(thread) => thread.join()
         case Right(process) => process.waitFor()
       }
   ```
   So if the CLI gets stuck in an infinite loop or is blocked waiting for input then this will hang forever. There really isn't much looping logic in the CLI itself, so if this did hang it probably means there is a bug Daffodil core causing an infinite loop, which would probably also cause TDML tests to hang. Or more likely it means the test body is broken and the CLI is expecting input on stdin and the test body isn't providing it.
   
   The other places that could now hang are the tests related to socket reading where there are potentially blocking reads. But those are very unlikely to hang since the tests are written correctly so the reads shouldn't block, and Java isn't likely to change the blocking behavior of sockets, so our tests making sure reads don't block will likely never fail and never need to change.
   
   I do agree that it's worth adding comments to these places in the CLI where a hang is theoretically possible and what could cause it.
   
   > I think if this spins 10 times (1 full second) or maybe 20 times, then it should start outputting something to somewhere like stderr indicating that it seems to be stuck.
   
   Just playing devils advocate, we don't do anything like this for any other tests, either unit or TDML. And IMO, all our other tests have just as much a likelihood to to enter an infinite loop as these tests (which I argue are both very unlikely). And if they happened, then it would be consistent and easily repeatable.
   
   I do admit that these CLI tests are definitely more complicated with the different thread interactions, but expect ignoring interrupts feels very unlikely. So practically the only place this runCLI will hang is with a infinite loop in the CLI (also feels unlikely, and would likely show up in TDML tests that would hang) or if the test body is broken and leaves the CLI hanging (e.g. the CLI is at a debugger breakpoint waiting for debugger commands, the CLI is reading from stdin and doesn't provide the right input/never closes stdin).
   
   In fact, we had one test that actually did leave the CLI hanging waiting for debug input and these changes made it very obvious and repeatable. The test hung at the cliThread join() call, it needed a Ctrl-C to kill the test, and sbt output the exception that looked like this
   
   ```
   [error] Test org.apache.daffodil.cliTest.TestCLIdebugger.test_3585_CLI_Debugger_simpleDebugger_unparse failed: java.lang.InterruptedException: null, took 12.068 sec
   [error]     at java.lang.Object.wait(Native Method)
   [error]     at java.lang.Thread.join(Thread.java:1257)
   [error]     at java.lang.Thread.join(Thread.java:1331)
   [error]     at org.apache.daffodil.CLI.Util$.runCLI(Util.scala:257)
   [error]     at org.apache.daffodil.cliTest.TestCLIdebugger.test_3585_CLI_Debugger_simpleDebugger_unparse(TestCLIDebugger.scala:873)
   ```
   
   So I knew exactly which test it was and which join it was hanging on. And it turned out the test was just broken and missing a debugger `"quit"` command, fixed in this PR.
   
   We could definitely put a time limit on the CLI joins and start outputting messages (like "CLI loop is taking longer than expected") like you suggest, but those are just going to be false negatives more often than not. Tests taking longer than expected due to resource constrains is what led to randomly failing PRs. Random error messages with tests still passing may just confuse things more. And with a Ctrl-C we get precise information about which test and which join was hung.



##########
daffodil-cli/src/test/scala/org/apache/daffodil/CLI/Util.scala:
##########
@@ -228,11 +227,12 @@ object Util {
         (toIn, fromOut, fromErr, Left(thread))
       }
 
+    // Create an ExpectIt object that reads/writes the streams created above
     val eb = new ExpectBuilder()
     eb.withOutput(toIn)
     eb.withInputs(fromOut, fromErr)
     eb.withInputFilters(replaceInString("\r\n", "\n"))
-    eb.withTimeout(timeout, TimeUnit.SECONDS)
+    eb.withInfiniteTimeout()

Review Comment:
   That's kind of what happens now, but I think it's actually more useful than a "thread taking too long" kind of message.
   
   With this change, we tell expect to never timeout (i.e. infinite timeout), but then run all the expect logic in a separate thread (the new TestThread class). Once the CLI is done, we give `timeout` seconds for the test thread to finish up all its checks and interrupt the thread if it reaches that timeout. That interrupt causes the test thread to die, we capture the exception caused by the interrupt, and rethrow it in the main thread for sbt to output.
   
   So essentially we tell expect to not do timeout logic and we do it ourselves. The idea being that we don't want expect to timeout until after the CLI is done. Otherwise long CLI startup times can lead to expect failures.
   
   Note that if it does hit that timeout (e.g. if I add a long `Thread.sleep` in a test body), we get something like this:
   
   ```
   Test org.apache.daffodil.cliTest.TestCLIparsing.test_3677_CLI_Parsing_elementFormDefault_qualified failed: java.lang.InterruptedException: sleep interrupted, took 11.973 sec
   [error]     at java.lang.Thread.sleep(Native Method)
   [error]     at org.apache.daffodil.cliTest.TestCLIparsing.$anonfun$test_3677_CLI_Parsing_elementFormDefault_qualified$1(TestCLIParsing.scala:34)
   ```
   
   Or if a test body expects something that doesn't exist, we get this:
   ```
   [error] Test org.apache.daffodil.cliTest.TestCLIparsing.test_3677_CLI_Parsing_elementFormDefault_qualified failed: net.sf.expectit.ExpectIOException: Expect operation fails (timeout: -1 ms) for matcher: contains('<tns:e1>does not exist</tns:e1>'), took 4.863 sec
   [error]     at net.sf.expectit.ExpectImpl.expectIn(ExpectImpl.java:106)
   [error]     at net.sf.expectit.AbstractExpectImpl.expectIn(AbstractExpectImpl.java:57)
   [error]     at net.sf.expectit.AbstractExpectImpl.expect(AbstractExpectImpl.java:61)
   [error]     at org.apache.daffodil.CLI.Util$CLITester.expect(Util.scala:464)
   [error]     at org.apache.daffodil.cliTest.TestCLIparsing.$anonfun$test_3677_CLI_Parsing_elementFormDefault_qualified$1(TestCLIParsing.scala:34)
   ```
   
   In both of these examples, we get a line number that says exactly which line in the testBody expect was at when it was interrupted.
   
   I'll add some comments to make it more clear and why this infinite timeout isn't really infinite.



-- 
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.

To unsubscribe, e-mail: commits-unsubscribe@daffodil.apache.org

For queries about this service, please contact Infrastructure at:
users@infra.apache.org