Add a logger to Retry, and make the integration tests Retry effective (#4793)

This adds a `logger: String => Unit` argument to `Retry`, so that we can
know in the logs (CI logs say) if a retry did happen. Two helpers are
added to help users pass that new argument: `Retry.ctxLogger` that uses
`Task.ctx`, and `Retry.printStream` if one wants to log with
`System.err` for example.

Also, this moves the `Retry` of integration tests from
`UtestIntegrationTestSuite` to `IntegrationTestSuite#integrationTest`.
In the former location, it was wrapping a `Future`, which `Retry`
doesn't handle, so that the retry actually had no effect I think.

Lastly, this ignores `TimeoutException`s for example tests that have a
`ignoreErrorsOnCI` file (introduced in
#4751).

Author: alexarchambault

main/util/src/mill/util/Retry.scala

@@ -1,12 +1,18 @@
 package mill.util
 
+import mill.api.Ctx
+
+import java.io.{ByteArrayOutputStream, PrintStream}
+import java.nio.charset.StandardCharsets
 import java.util.concurrent.TimeUnit
+
 import scala.concurrent.duration.Duration
 import scala.concurrent.{Await, Promise}
 
 /**
  * Generic retry functionality
  *
+ * @param logger            Method to log messages upon failure
  * @param count             How many times to retry before giving up
  * @param backoffMillis     What is the initial backoff time
  * @param backoffMultiplier How much to multiply the initial backoff each time
@@ -21,6 +27,7 @@ import scala.concurrent.{Await, Promise}
  *         [[t]] fails more than [[count]] times
  */
 case class Retry(
+    logger: String => Unit,
     count: Int = 5,
     backoffMillis: Long = 10,
     backoffMultiplier: Double = 2.0,
@@ -46,6 +53,8 @@ case class Retry(
         }
       } catch {
         case e: Throwable if retryCount < count && filter(retryCount + 1, e) =>
+          logger(Retry.printException(e))
+          logger(s"Attempt ${retryCount + 1} failed, waiting $currentBackoffMillis ms")
           Thread.sleep(currentBackoffMillis)
           rec(retryCount + 1, (currentBackoffMillis * backoffMultiplier).toInt)
       }
@@ -54,3 +63,20 @@ case class Retry(
     rec(0, backoffMillis)
   }
 }
+
+object Retry {
+
+  /** Use this logger to log from a Mill task */
+  def ctxLogger(implicit ctx: Ctx.Log): String => Unit =
+    ctx.log.warn(_)
+
+  /** Use this logger to log with a `PrintStream`, such as `System.err` */
+  def printStreamLogger(printStream: PrintStream): String => Unit =
+    printStream.println(_)
+
+  private def printException(ex: Throwable): String = {
+    val baos = new ByteArrayOutputStream
+    ex.printStackTrace(new PrintStream(baos, true, StandardCharsets.UTF_8))
+    new String(baos.toByteArray, StandardCharsets.UTF_8)
+  }
+}

main/util/test/src/mill/util/RetryTests.scala

@@ -7,7 +7,7 @@ object RetryTests extends TestSuite {
     test("fail") {
       var count = 0
       try {
-        Retry() {
+        Retry(Retry.printStreamLogger(System.err)) {
           count += 1
           throw new Exception("boom")
         }
@@ -20,7 +20,7 @@ object RetryTests extends TestSuite {
     }
     test("succeed") {
       var count = 0
-      Retry() {
+      Retry(Retry.printStreamLogger(System.err)) {
         count += 1
         if (count < 3) throw new Exception("boom")
       }
@@ -30,6 +30,7 @@ object RetryTests extends TestSuite {
       var count = 0
       try {
         Retry(
+          Retry.printStreamLogger(System.err),
           filter = {
             case (i, ex: RuntimeException) => true
             case _ => false
@@ -49,7 +50,7 @@ object RetryTests extends TestSuite {
       test("fail") {
         var count = 0
         try {
-          Retry(timeoutMillis = 100) {
+          Retry(Retry.printStreamLogger(System.err), timeoutMillis = 100) {
             count += 1
             Thread.sleep(1000)
           }
@@ -62,7 +63,7 @@ object RetryTests extends TestSuite {
       }
       test("success") {
         var count = 0
-        Retry(timeoutMillis = 100) {
+        Retry(Retry.printStreamLogger(System.err), timeoutMillis = 100) {
           count += 1
           if (count < 3) Thread.sleep(1000)
         }

scalalib/worker/src/mill/scalalib/worker/ZincWorkerImpl.scala

@@ -231,7 +231,7 @@ class ZincWorkerImpl(
     ) { (compilers: Compilers) =>
       // Not sure why dotty scaladoc is flaky, but add retries to workaround it
       // https://github.com/com-lihaoyi/mill/issues/4556
-      mill.util.Retry(count = 2) {
+      mill.util.Retry(mill.util.Retry.ctxLogger, count = 2) {
         if (
           ZincWorkerUtil.isDotty(scalaVersion) || ZincWorkerUtil.isScala3Milestone(scalaVersion)
         ) {

testkit/src/mill/testkit/IntegrationTestSuite.scala

@@ -1,7 +1,10 @@
 package mill.testkit
 
+import mill.util.Retry
 import os.Path
 
+import scala.concurrent.duration.DurationInt
+
 trait IntegrationTestSuite {
 
   /**
@@ -39,15 +42,21 @@ trait IntegrationTestSuite {
    * given [[block]].
    */
   def integrationTest[T](block: IntegrationTester => T): T = {
-    val tester = new IntegrationTester(
-      clientServerMode,
-      workspaceSourcePath,
-      millExecutable,
-      debugLog,
-      baseWorkspacePath = os.pwd,
-      propagateJavaHome = propagateJavaHome
-    )
-    try block(tester)
-    finally tester.close()
+    Retry(
+      Retry.printStreamLogger(System.err),
+      count = if (sys.env.contains("CI")) 1 else 0,
+      timeoutMillis = 10.minutes.toMillis
+    ) {
+      val tester = new IntegrationTester(
+        clientServerMode,
+        workspaceSourcePath,
+        millExecutable,
+        debugLog,
+        baseWorkspacePath = os.pwd,
+        propagateJavaHome = propagateJavaHome
+      )
+      try block(tester)
+      finally tester.close()
+    }
   }
 }

testkit/src/mill/testkit/IntegrationTesterBase.scala

@@ -39,7 +39,7 @@ trait IntegrationTesterBase {
   def initWorkspace(): Unit = {
     println(s"Copying integration test sources from $workspaceSourcePath to $workspacePath")
     os.makeDir.all(workspacePath)
-    Retry() {
+    Retry(Retry.printStreamLogger(System.err)) {
       val tmp = os.temp.dir()
       val outDir = os.Path(out, workspacePath)
       if (os.exists(outDir)) os.move.into(outDir, tmp)

testkit/src/mill/testkit/UtestExampleTestSuite.scala

@@ -3,6 +3,8 @@ package mill.testkit
 import mill.util.Retry
 import utest._
 
+import java.util.concurrent.TimeoutException
+
 import scala.concurrent.duration.DurationInt
 
 object UtestExampleTestSuite extends TestSuite {
@@ -13,16 +15,31 @@ object UtestExampleTestSuite extends TestSuite {
   val tests: Tests = Tests {
 
     test("exampleTest") {
-      Retry(
-        count = if (sys.env.contains("CI")) 1 else 0,
-        timeoutMillis = 15.minutes.toMillis
-      ) {
-        ExampleTester.run(
-          clientServerMode,
-          workspaceSourcePath,
-          millExecutable
-        )
-      }
+      def run() =
+        Retry(
+          Retry.printStreamLogger(System.err),
+          count = if (sys.env.contains("CI")) 1 else 0,
+          timeoutMillis = 15.minutes.toMillis
+        ) {
+          ExampleTester.run(
+            clientServerMode,
+            workspaceSourcePath,
+            millExecutable
+          )
+        }
+
+      val ignoreErrors = System.getenv("CI") != null &&
+        os.exists(workspaceSourcePath / "ignoreErrorsOnCI")
+      if (ignoreErrors)
+        try run()
+        catch {
+          case _: TimeoutException =>
+            System.err.println(
+              s"Found ignoreErrorsOnCI under $workspaceSourcePath, ignoring timeout exception"
+            )
+        }
+      else
+        run()
     }
   }
 }

testkit/src/mill/testkit/UtestIntegrationTestSuite.scala

@@ -1,9 +1,5 @@
 package mill.testkit
 
-import mill.util.Retry
-import scala.concurrent.duration.DurationInt
-import scala.concurrent.{ExecutionContext, Future}
-
 abstract class UtestIntegrationTestSuite extends utest.TestSuite with IntegrationTestSuite {
   protected def workspaceSourcePath: os.Path = os.Path(sys.env("MILL_TEST_RESOURCE_DIR"))
   protected def clientServerMode: Boolean = sys.env("MILL_INTEGRATION_SERVER_MODE").toBoolean
@@ -13,15 +9,4 @@ abstract class UtestIntegrationTestSuite extends utest.TestSuite with Integratio
     sys.env("MILL_INTEGRATION_IS_PACKAGED_LAUNCHER").toBoolean
   protected def millExecutable: os.Path =
     os.Path(System.getenv("MILL_INTEGRATION_LAUNCHER"), os.pwd)
-
-  override def utestWrap(path: Seq[String], runBody: => Future[Any])(implicit
-      ec: ExecutionContext
-  ): Future[Any] = {
-    Retry(
-      count = if (sys.env.contains("CI")) 1 else 0,
-      timeoutMillis = 10.minutes.toMillis
-    ) {
-      super.utestWrap(path, runBody)
-    }
-  }
 }