Test Flake: Unit test cmd/entrypoint TestRealRunnerTimeout

[lbernick]

Sadly not much info present in log file:

=== RUN   TestRealRunnerTimeout
    runner_test.go:37: step didn't timeout
--- FAIL: TestRealRunnerTimeout (0.03s)

/kind flake
/priority important-soon

[lbernick]

This could be fixed by rewriting waiter.Wait to use the k8s Clock.Sleep, and the test to use FakeClock.Sleep.

[tekton-robot]

Issues go stale after 90d of inactivity.
Mark the issue as fresh with /remove-lifecycle stale with a justification.
Stale issues rot after an additional 30d of inactivity and eventually close.
If this issue is safe to close now please do so with /close with a justification.
If this issue should be exempted, mark the issue as frozen with /lifecycle frozen with a justification.

/lifecycle stale

Send feedback to tektoncd/plumbing.

[abayer]

/lifecycle frozen

I hit this one while trying to reproduce the various events-related flakes, so it's still a thing. I thought that maybe increasing the timeout in the test would help, but I seem to still be hitting it...

[abayer]

Oh, and I reproduced it with this:

while go test -race -count 100 -v ./cmd/entrypoint > flake-log; do :; done

[abayer]

...and now I can't reproduce it at all! Fun times.

[abayer]

Yeah, it failing or not depended on what I had for -count and the overall load on my system, not on anything flaky. Sigh. Well, it's still a flake, just one I can't come up with a fix for...

[Yongxuanzhang]

I'm looking into this issue and I'm not sure what the testcase wants to test. From the test description it wants to test that the runner will be killed after a millisecond (though it wants to sleep 10 ms?),

pipeline/cmd/entrypoint/runner_test.go

Line 123 in 0b8349b

// TestRealRunnerTimeout tests whether cmd is killed after a millisecond even though it's supposed to sleep for 10 milliseconds.

and the DeadlineExceeded error can be retuned in 2 places:

pipeline/cmd/entrypoint/runner.go

Lines 120 to 125 in f83cd1f

	if err := cmd.Start(); err != nil {
	if ctx.Err() == context.DeadlineExceeded {
	return context.DeadlineExceeded
	}
	return err
	}

pipeline/cmd/entrypoint/runner.go

Lines 154 to 158 in f83cd1f

	if err := cmd.Wait(); err != nil {
	if ctx.Err() == context.DeadlineExceeded {
	return context.DeadlineExceeded
	}
	return err

It seems that the DeadlineExceeded can still be returned if the runner really sleep 10 ms?

[lbernick]

I'm looking into this issue and I'm not sure what the testcase wants to test. From the test description it wants to test that the runner will be killed after a millisecond (though it wants to sleep 10 ms?),

The command here that the entrypoint is supposed to be running is "sleep 10ms". This test ensures that the runner can be timed out in the appropriate time. i.e. it wants to ensure that the runner times out after 1ms even though the command is not done.

It seems that the DeadlineExceeded can still be returned if the runner really sleep 10 ms?

Maybe? If so, that would mean that our tests could pass because the runner finished running and not because it got timed out correctly, which isn't great. (I suspect our timeout logic works correctly but ideally our tests should tell us this!) To test out whether or not this could happen, you could set the timeout to a very long time, and see if the tests still pass when the "sleep" command completes after 10ms.

[Yongxuanzhang]

From the test and code, it uses context.WithTimeout(context.Background(), timeout) this timeout ctx to count the time, and the ctx is also added to the cmd, right now the error is returned here:

pipeline/cmd/entrypoint/runner.go

Line 120 in 09c7285

if err := cmd.Start(); err != nil {

And if we jump into the Start(), it will return before the process is created to execute the cmd b/c the ctx is already done with timeout err, it this expected?

So I'm curious if the test is really testing what it says. Or maybe my understanding is wrong

[Yongxuanzhang]

/assign