cmd/go/internal/lockedfile: avoid failing tests due to arbitrary timeouts

The mustBlock helper returns a function that verifies that the blocked
operation does eventually complete. However, it used an arbitrary
10-second timeout in place of “eventually”.

Since the test is checking a synchronization library, bugs are likely
to manifest as deadlocks. It may be useful to log what operation is in
flight if such a deadlock occurs; however, since we can't bound how
long a “reasonable” operation should take, the log message should only
be informational — it should not cause the test to fail.

While we're here, let's also set a better example by not leaking
time.After timers in the tests..

Fixes #57592.

Change-Id: I4e74e42390679bffac7a286824acb71b08994c17
Reviewed-on: https://go-review.googlesource.com/c/go/+/461000
Reviewed-by: Damien Neil <dneil@google.com>
TryBot-Result: Gopher Robot <gobot@golang.org>
Run-TryBot: Bryan Mills <bcmills@google.com>
Auto-Submit: Bryan Mills <bcmills@google.com>

diff --git a/src/cmd/go/internal/lockedfile/lockedfile_test.go b/src/cmd/go/internal/lockedfile/lockedfile_test.go
index 5f6153cb15d1e6e9d508e59c2ea8aa53e5861c9b..6b54654ac72e444931c42d03de2e688040befe50 100644 (file)
--- a/src/cmd/go/internal/lockedfile/lockedfile_test.go
+++ b/src/cmd/go/internal/lockedfile/lockedfile_test.go
@@ -43,19 +43,32 @@ func mustBlock(t *testing.T, desc string, f func()) (wait func(*testing.T)) {
                close(done)
        }()
 
+       timer := time.NewTimer(quiescent)
+       defer timer.Stop()
        select {
        case <-done:
                t.Fatalf("%s unexpectedly did not block", desc)
-               return nil
+       case <-timer.C:
+       }
+
+       return func(t *testing.T) {
+               logTimer := time.NewTimer(quiescent)
+               defer logTimer.Stop()
 
-       case <-time.After(quiescent):
-               return func(t *testing.T) {
+               select {
+               case <-logTimer.C:
+                       // We expect the operation to have unblocked by now,
+                       // but maybe it's just slow. Write to the test log
+                       // in case the test times out, but don't fail it.
                        t.Helper()
-                       select {
-                       case <-time.After(probablyStillBlocked):
-                               t.Fatalf("%s is unexpectedly still blocked after %v", desc, probablyStillBlocked)
-                       case <-done:
-                       }
+                       t.Logf("%s is unexpectedly still blocked after %v", desc, quiescent)
+
+                       // Wait for the operation to actually complete, no matter how long it
+                       // takes. If the test has deadlocked, this will cause the test to time out
+                       // and dump goroutines.
+                       <-done
+
+               case <-done:
                }
        }
 }
@@ -244,10 +257,12 @@ locked:
                if _, err := os.Stat(filepath.Join(dir, "locked")); !os.IsNotExist(err) {
                        break locked
                }
+               timer := time.NewTimer(1 * time.Millisecond)
                select {
                case <-qDone:
+                       timer.Stop()
                        break locked
-               case <-time.After(1 * time.Millisecond):
+               case <-timer.C:
                }
        }