From ca82cb63ab20c44a48536bc494a4828414b35cfb Mon Sep 17 00:00:00 2001 From: Raphael 'kena' Poss Date: Thu, 25 Aug 2022 12:23:51 +0000 Subject: [PATCH] acceptance: avoid races in the health assertion Prior to this patch, the Assert code was reading events from the docker event channel too fast, possibly missing some events in the process. It is because the events were read too fast that the problem fixed in the previous commit did not always result in a test crash/failure (i.e. the assert was too fast to do its job properly in most cases). By slowing down the reading of events from docker, we can surface logic error in the surrounding test framework more clearly. Release justification: non-production code changes Release note: None --- pkg/acceptance/cluster/dockercluster.go | 16 +++++++++++++--- 1 file changed, 13 insertions(+), 3 deletions(-) diff --git a/pkg/acceptance/cluster/dockercluster.go b/pkg/acceptance/cluster/dockercluster.go index 0fef62f91997..536190e8402d 100644 --- a/pkg/acceptance/cluster/dockercluster.go +++ b/pkg/acceptance/cluster/dockercluster.go @@ -668,7 +668,6 @@ func (l *DockerCluster) Start(ctx context.Context) { // the cluster (restart, kill, ...). In the event of a mismatch, the passed // Tester receives a fatal error. func (l *DockerCluster) Assert(ctx context.Context, t testing.TB) { - const almostZero = 50 * time.Millisecond filter := func(ch chan Event, wait time.Duration) *Event { select { case act := <-ch: @@ -680,17 +679,28 @@ func (l *DockerCluster) Assert(ctx context.Context, t testing.TB) { var events []Event for { + // The expected event channel is buffered and should contain + // all expected events already. + const almostZero = 15 * time.Millisecond exp := filter(l.expectedEvents, almostZero) if exp == nil { break } - act := filter(l.events, 15*time.Second) + t.Logf("expecting event: %v", exp) + // l.events is connected to the docker controller and may + // receive events more slowly. + const waitForDockerEvent = 15 * time.Second + act := filter(l.events, waitForDockerEvent) + t.Logf("got event: %v", act) if act == nil || *exp != *act { t.Fatalf("expected event %v, got %v (after %v)", exp, act, events) } events = append(events, *exp) } - if cur := filter(l.events, almostZero); cur != nil { + // At the end, we leave docker a bit more time to report a final event, + // if any. + const waitForLastDockerEvent = 1 * time.Second + if cur := filter(l.events, waitForLastDockerEvent); cur != nil { t.Fatalf("unexpected extra event %v (after %v)", cur, events) } if log.V(2) {