assert: Eventually should not leak a goroutine

[dolmen]

Description

If the condition function runs for longer than the timeout given to assert.Eventually (and family: EventuallyWithT, Never) it returns anyway right after the timeout, and the goroutine in which the condition runs continues in the background beyond Eventually returns. This is a goroutine leak that can lead to dirty bugs and flaky tests.

Note that the Eventually internal test suite TestEventuallyWithT_ReturnsTheLatestFinishedConditionErrors and TestEventuallyTimeout rely on this behavior so we first have to fix those 2 tests.

Step To Reproduce

On the Go Playground: https://go.dev/play/p/mDyUOIJXQS5

func TestEventuallyLeak(t *testing.T) {
    done := make(chan struct{})

    inEventually := true
    assert.Eventually(t, func() bool {
        defer func() {
            t.Log(time.Now(), "Condition: end.")
            done <- struct{}{}
        }()
        t.Log(time.Now(), "Condition: inEventually =", inEventually)
        time.Sleep(500 * time.Millisecond)
        t.Log(time.Now(), "Condition: inEventually =", inEventually)
        return true
    }, 100*time.Millisecond, 10*time.Millisecond)
    inEventually = false
    t.Log(time.Now(), "Eventually done")

    <-done
    t.Log(time.Now(), "End of", t.Name())
}

Expected behavior

Every log happening in the condition should happen before "Eventually done".

Actual behavior

=== RUN   TestEventuallyLeak
    prog_test.go:19: 2009-11-10 23:00:00.01 +0000 UTC m=+0.010000001 Condition: inEventually = true
    prog_test.go:14: 
            Error Trace:    /tmp/sandbox257157838/prog_test.go:14
            Error:          Condition never satisfied
            Test:           TestEventuallyLeak
    prog_test.go:25: 2009-11-10 23:00:00.1 +0000 UTC m=+0.100000001 Eventually done
    prog_test.go:21: 2009-11-10 23:00:00.51 +0000 UTC m=+0.510000001 Condition: inEventually = false
    prog_test.go:16: 2009-11-10 23:00:00.51 +0000 UTC m=+0.510000001 Condition: end.
    prog_test.go:28: 2009-11-10 23:00:00.51 +0000 UTC m=+0.510000001 End of TestEventuallyLeak
--- FAIL: TestEventuallyLeak (0.51s)
FAIL

[dolmen]

Cc: @cszczepaniak

[dolmen]

Here is a test that we will add to the testsuite to detect this wrong behavior:

type dummyT struct{}

func (dummyT) Errorf(string, ...any) {}

func TestEventuallyNoLeak(t *testing.T) {
    done := make(chan bool)

    inEventually := true
    assert.Eventually(dummyT{}, func() bool {
        defer func() {
            done <- inEventually
        }()
        time.Sleep(500 * time.Millisecond)
        return true
    }, 100*time.Millisecond, 10*time.Millisecond)
    inEventually = false
    assert.True(t, <-done, "Condition should end while Eventually still runs.")
}

Currently failing:

=== RUN   TestEventuallyNoLeak
    prog_test.go:26: 
            Error Trace:    /tmp/sandbox2322949621/prog_test.go:26
            Error:          Should be true
            Test:           TestEventuallyNoLeak
            Messages:       Condition should end while Eventually still runs.
--- FAIL: TestEventuallyNoLeak (0.51s)
FAIL

[z0marlin]

In the above test, even though Eventually should wait for the condition to finish, I'm assuming that the Eventually test should still fail since the condition could not be true within the waitFor duration. Is that right?

[dolmen]

My proposal:

1. the expiration time is defined as: waitFor + 1 * tick
2. we should ignore the result of a condition that finishes after the expiration time
3. we should raise an error if the condition finishes after the expiration time: that error should help the developer to fix a test that might be flaky because of timing issues
4. that error must not affect the boolean result returned by the function. (This is important for Never: we might raise an error because of the condition going beyond the expiration time, but that error must not affect whether the condition has been satisfied in the specified duration)

Notes:

• about 1. this should formula should handle the case where waitFor is a multiple of tick and the last tick happens just before waitFor expires
• about 3. I wonder if we should go further and report any case of the condition running for a duration longer than the tick

[z0marlin]

I wonder if we should go further and report any case of the condition running for a duration longer than the tick.

As per the API, Eventually runs the condition func every tick. But that only holds true if the condition func finishes before the next tick. Reporting such cases would be good as it will let the developers know that the test is not behaving as expected.

[z0marlin]

that error must not affect the boolean result returned by the function.

Need some more clarity on this. Say we have the following tests:

func Test1(t *testing.T) {
    condition := func() bool {
        time.Sleep(50 * time.Millisecond)
        return true
    }

    Eventually(t, condition, 20*time.Millisecond, 5*time.Millisecond) // should raise an error for long condition func and return false
    Never(t, condition, 20*time.Millisecond, 5*time.Millisecond)      // should raise an error for long condition func and return true
}

func Test2(t *testing.T) {
    condition := func() bool {
        time.Sleep(50 * time.Millisecond)
        return false
    }

    Eventually(t, condition, 20*time.Millisecond, 5*time.Millisecond) // should raise an error for long condition func and return false
    Never(t, condition, 20*time.Millisecond, 5*time.Millisecond)      // should raise an error for long condition func and return true
}

Do the comments reflect the expected behaviour in each of the cases?

[dolmen]

@z0marlin wrote:

Do the comments reflect the expected behaviour in each of the cases?

Yes.

[z0marlin]

I wonder if we should go further and report any case of the condition running for a duration longer than the tick.

As per the API, Eventually runs the condition func every tick. But that only holds true if the condition func finishes before the next tick. Reporting such cases would be good as it will let the developers know that the test is not behaving as expected.

This would be a breaking change I suppose as it could fail some of the existing tests.

[anonmanak2000]

Here is a test that we will add to the testsuite to detect this wrong behavior:

type dummyT struct{}

func (dummyT) Errorf(string, ...any) {}

func TestEventuallyNoLeak(t *testing.T) {
  done := make(chan bool)

  inEventually := true
  assert.Eventually(dummyT{}, func() bool {
      defer func() {
          done <- inEventually
      }()
      time.Sleep(500 * time.Millisecond)
      return true
  }, 100*time.Millisecond, 10*time.Millisecond)
  inEventually = false
  assert.True(t, <-done, "Condition should end while Eventually still runs.")
}

Currently failing:

=== RUN   TestEventuallyNoLeak
    prog_test.go:26: 
          Error Trace:    /tmp/sandbox2322949621/prog_test.go:26
          Error:          Should be true
          Test:           TestEventuallyNoLeak
          Messages:       Condition should end while Eventually still runs.
--- FAIL: TestEventuallyNoLeak (0.51s)
FAIL

I am trying to understand here. But doesn't it defeat the purpose of providing the waitfor? If the condition overruns the waitfor duration, ideally, Eventually should throw an error along with condition to stop executing further. Apologies, if I misunderstood anything!

[z0marlin]

But doesn't it defeat the purpose of providing the waitfor? If the condition overruns the waitfor duration, ideally, Eventually should throw an error along with condition to stop executing further.

@anonmanak2000 the proposal here is somewhat similar. We want to throw an error when the condition exceeds waitFor duration. However, since the condition runs in a separate go routine, we need to ensure that the go routine finishes before we return from Eventually.

[z0marlin]

@dolmen the proposal looks good, but I have concerns around:

the expiration time is defined as: waitFor + 1 * tick

I wonder if we should go further and report any case of the condition running for a duration longer than the tick

Both of these seem like breaking changes to me. Wdyt?

[brackendawson]

I think this (and every other problem with Eventually) is solved by making the call to condition synchronous (but in a goroutine for CollectT to work). This is a reasonably significant change in behaviour, we can solve this by making a new assertion and deprecating the old ones. I've opened a PR showing what I mean.