Deflake integration tests #1599

ldez · 2017-05-13T23:12:53Z

Description

Base on #1284

vdemeester

Nice improvements @ldez 👍 Left a few comments.

Also:

We could go even farther on this, mimicing a bit what I started to do on docker integration request package — i.e. instead of requiring the test to create the Request, etc.. just call Request(…) with the correct arguments.
We could try to make Try more composable (so you could do Try(…, Request(…), conditions..)), etc..
Finaly, as it's a testing package, we could even make the Try function take a t *testing.T as first argument, and calling t.Fatal in case of error 👼

vdemeester · 2017-05-14T07:50:21Z

integration/access_log_test.go

@@ -12,6 +12,7 @@ import (
 	"strings"
 	"time"

+	"github.com/containous/traefik/integration/utils"


I know this isn't related to this PR, but integration/try would make more sense (and removing Try from function names)

vdemeester · 2017-05-14T07:58:24Z

integration/utils/try.go

+		return nil
+	}
+
+	stopTime := time.Now().Add(timeout)


stopTimer := time.NewTimer(timeout) retryTick := time.NewTicker(interval) for { select { case <-stopTimer.C: err = fmt.Errorf("try operation failed: %s", err) break case <-retryTick.C: if err = operation(); err == nil { // do your thing break } } } // This also can be done inside the loop, in the retryTick.C case stopTimer.Stop() retryTick.Stop() return nil

Your code doesn't work -> infinite timeout when the operation failed.

for { select { case <-time.After(timeout): return fmt.Errorf("try operation failed: %s", err) case <-time.Tick(wait): if err = operation(); err == nil { return nil } } }

-> infinite timeout when the operation failed.

stopTimer := time.NewTimer(timeout) retryTick := time.NewTicker(interval) for { select { case <-stopTimer.C: err = fmt.Errorf("try operation failed: %s", err) stopTimer.Stop() retryTick.Stop() return err case <-retryTick.C: if err = operation(); err == nil { stopTimer.Stop() retryTick.Stop() return err } } }

-> works but not very beautiful.

Your code doesn't work -> infinite timeout when the operation failed.

Why would it ? at some point (timeout) stopTimer.C will get the message and we get out of the infinit loop.

I don't know exactly why but it produce an infinite loop.
it produce 2 loops: one stop at the timeout and one infinite.

vdemeester · 2017-05-14T08:00:32Z

integration/utils/try.go

+		interval = maxInterval
+	}
+
+	ci := os.Getenv("CI")


I'm really not a huge fan of that. We shouldn't have a special case for CI. If we need a 3x multiplier for timeout in CI, let's just set all the timeout to 3x their value..

Currently, this doesn't work because we don't access to global env var in the integration test.

But why I have add this special case?
I don't want to wait 3 min in my local environment to known if a test fail, but in the CI some tests are more slow than a personal computer, we need to have a pragmatic approach.

Currently, this doesn't work because we don't access to global env var in the integration test.

hum.. 🤔 we have access to whichever the environment variable used to execute the tests, so we just need to pass them.

But why I have add this special case?
I don't want to wait 3 min in my local environment to known if a test fail, but in the CI some tests are more slow than a personal computer, we need to have a pragmatic approach.

hum, I don't really buy that but meh I won't fight again, it's just timeout stuff

Currently, this doesn't work because we don't access to global env var in the integration test.

hum.. 🤔 we have access to whichever the environment variable used to execute the tests, so we just need to pass them.

in our repo via .semaphoreci/vars we can pass global vars to the CI, but in this case the issue is the overlay docker level (which adds a filter).
To be visible during the tests, The CI global vars need to be passed in the make file like that: atbore-phx@6aef257

CI log

I'm really not a huge fan of that. We shouldn't have a special case for CI. If we need a 3x multiplier for timeout in CI, let's just set all the timeout to 3x their value..

I'm agree "in theory" with this sentence if we are speaking about "timeout" stuff,
but i feel, I'm missing something, just to understand, why do we wait 3 min more, locally ? the value is a timeout so a max "break" value. isn't it ?

I have already experienced cases where I had run into integration test timeouts locally only when my laptop was running under high CPU load. Other machines with less or more resources could behave totally differently.

This is really a classical case of YMMV. I'm with @vdemeester that we should just swallow the pill and increase the timeouts globally. For the vast majority of cases, we won't feel the slowdown because the tests will complete quickly enough. For those cases where we experience lots of long-running failing tests, you'd probably start them individually anyway because nobody is going to wait 60, 120, or 180 seconds for a whole bunch of failing integration tests to complete.

Finally, the purpose of this PR is to reduce flakiness, and not waiting long enough is a source of flakiness. I'd rather eliminate this risk and pay the price that things will be a bit slower than necessary if things go south temporarily.

vdemeester · 2017-05-14T08:02:43Z

integration/utils/try.go

+
+// Sleep pauses the current goroutine for at least the duration d.
+// Use only when use an other Try[...] functions is not possible.
+func Sleep(d time.Duration) {


If we don't have a special case for CI, this doesn't make sense. We should be able to replace any time.Sleep from the tests code with a Try or sthg that is better than a plain old Sleep

Currently, in some case we really need to use time.Sleep, the Try logical cannot solve all case.
We need a second way with a stuff like: "Retry again for X time"

Loads of cases should/can be handled with Try or something that acting almost the same.

If we Sleep :

when waiting for the process to run, we should use Try with a condition (i.e. something that checks the process is running, or some port is open, or for some output of the command to appear, or ?)

when waiting for a k/v value to be there, same, we should put the get into a condition

The less we use Sleep, the better really 👼

https://github.com/containous/traefik/blob/master/integration/marathon_test.go#L39

This case need a continue approach, try doesn't work in this case.

PS: this test file seems to test nothing, because all request seems always give the same response, look at the comment block (I have failed to make this work).

you can also look at https://github.com/containous/traefik/blob/master/integration/docker_test.go#L180

the first case (https://github.com/containous/traefik/blob/master/integration/marathon_test.go#L39) can handled with a Try

you can also look at https://github.com/containous/traefik/blob/master/integration/docker_test.go#L180

Yes, this one could/should use TryRequest (with the condition on getting a 404 or sthg)

vdemeester · 2017-05-14T08:09:12Z

integration/utils/try.go

+// Conditions are not allowed since it would complicate signaling if the
+// response body needs to be closed or not. Callers are expected to close on
+// their own if the function returns a nil error.
+func TryGetResponseUntilStatusCode(url string, timeout time.Duration, statusCode int) (*http.Response, error) {


This one is not used elsewhere

vdemeester · 2017-05-14T08:13:41Z

integration/utils/try.go

 		}
 		return nil
 	}
 }
+
+func doGetResponse(url string, timeout time.Duration, condition Condition) (*http.Response, error) {


This one is not required, let's just pass the http method to doResponse and use only doRespose

vdemeester · 2017-05-14T08:15:16Z

integration/consul_catalog_test.go


-	_, err = ioutil.ReadAll(resp.Body)
+	cond := utils.ComposeCondition(utils.UntilStatusCodeIs(200), utils.BodyContains("Welcome to nginx!"))
+	err = utils.TryRequest(req, 5*time.Second, cond)


I would have make TryRequest taking variadic args, so that you could do TryRequest(req, 5*time.Second, utils.UntilStatusCodeIs…, utils.Body…).

vdemeester · 2017-05-14T12:30:04Z

integration/healthcheck_test.go


-	resp, err = client.Do(req)
+	utils.Sleep(3 * time.Second)


I'm not sure about that one, at all. What are we testing here : that the health was 500 before (it's tested above) and that in a given period of time, it will be 200. I don't see why we re-verify 500, wait for 3s and then wait for 200.

we need to wait the time to do the check of the "healthcheck"

vdemeester · 2017-05-14T12:30:55Z

integration/healthcheck_test.go

+		c.Assert(err, checker.IsNil)
+	}
+
+	utils.Sleep(3 * time.Second)


Almost the same here, if we want to wait 3s and then have the TryRequest, let's just set a bigger timeout for the Try.

atbore-phx · 2017-05-14T14:17:57Z

when you think this PR reaches a steady state, just ping me and i could execute a series on the CI to verify if the Error Probability is decreasing like that: #1600.
IMHO: it could be a nice test to confirm if we are on the right direction before merge.
@ldez, @timoreimann it's a very nice work and improvement BTW.

ldez · 2017-05-14T16:32:33Z

Finaly, as it's a testing package, we could even make the Try function take a t *testing.T as first argument, and calling t.Fatal in case of error 👼

It's the first step, I will create the testing package after.

timoreimann · 2017-05-15T12:55:51Z

integration/access_log_test.go

@@ -71,14 +79,14 @@ func (s *AccessLogSuite) TestAccessLog(c *check.C) {
 			tokens, err := shellwords.Parse(line)
 			c.Assert(err, checker.IsNil)
 			c.Assert(len(tokens), checker.Equals, 13)
-			c.Assert(tokens[6], checker.Equals, "200")
+			c.Assert(regexp.MustCompile("^\\d\\d\\d$").MatchString(tokens[6]), checker.True)


Please use backticks instead of quotes to avoid extra escaping.

We should be able to specify directly how many digits we expect, i.e., \d{3}.

timoreimann · 2017-05-15T12:57:07Z

integration/acme_test.go

@@ -9,34 +9,24 @@ import (

 	"github.com/go-check/check"

-	"errors"
-	"github.com/containous/traefik/integration/utils"
+	"github.com/containous/traefik/integration/try"


Should go above line 10 to sort alphabetically.

timoreimann · 2017-05-15T13:01:30Z

integration/acme_test.go

@@ -65,12 +55,9 @@ func (s *AcmeSuite) TestRetrieveAcmeCertificate(c *check.C) {
 	client := &http.Client{Transport: tr}

 	// wait for traefik (generating acme account take some seconds)
-	err = utils.Try(30*time.Second, func() error {
+	err = try.Do(90*time.Second, func() error {


~~Why not use try.GetRequest?~~ Nevermind, sorry.

timoreimann · 2017-05-15T13:04:23Z

integration/consul_catalog_test.go

+		leader, err := consulClient.Status().Leader()
+
+		if err != nil || len(leader) == 0 {
+			return fmt.Errorf("Leader not find. %v", err)


s/find/found/

timoreimann · 2017-05-15T13:05:57Z

integration/consul_catalog_test.go


-	_, err = ioutil.ReadAll(resp.Body)
+	err = try.Request(req, 5*time.Second, try.StatusCodeIs(200), try.BodyContains("Welcome to nginx!"))


Do we need the extra BodyContains check? I'm worried it'll break if we change the Nginx image.

200 should be good enough, shouldn't it?

timoreimann · 2017-05-15T14:19:32Z

integration/healthcheck_test.go

 	c.Assert(err, checker.IsNil)

-	time.Sleep(time.Second * 3)
+	// Verify frontend health : before
+	err = try.Request(req, 3*time.Second, try.StatusCodeIs(500))


I don't think we need this.

timoreimann · 2017-05-15T14:21:30Z

integration/healthcheck_test.go


-	resp, err = client.Do(req)
+	try.Sleep(2 * time.Second)


I think we want another query check at this point rather making sure whoami1Host's health check returns 200 again.

timoreimann · 2017-05-15T14:24:33Z

integration/healthcheck_test.go

+	try.Sleep(2 * time.Second)
+
+	// Verify frontend health : 500
+	err = try.Request(req, 3*time.Second, try.StatusCodeIs(500))


...this should not be needed anymore.

timoreimann · 2017-05-15T14:32:30Z

integration/healthcheck_test.go

-	resp, err = client.Do(req)
+	try.Sleep(2 * time.Second)
+
+	// Verify frontend health : after


I think the block starting from here to line 91 (incl.) isn't needed as we just want the single, static request starting at line 93.

timoreimann · 2017-05-15T14:35:13Z

integration/https_test.go

@@ -25,7 +26,7 @@ func (s *HTTPSSuite) TestWithSNIConfigHandshake(c *check.C) {
 	c.Assert(err, checker.IsNil)
 	defer cmd.Process.Kill()

-	time.Sleep(500 * time.Millisecond)
+	try.Sleep(500 * time.Millisecond)


AFAICS, this should be the only try.Sleep call left after my comments regarding the other ones are addressed. What is this one waiting for? Isn't this just another "wait for Traefik to start" check that we tend to solve via a retriable request?

timoreimann

Wow, this is already a tremendously good PR @ldez. 👏

I think there are still 3 open points:

Health check test: I think the implementation is still susceptible to flakiness (primarily because of the try.Sleep usage) and that there's room for simplification. Please see my latest comments.
try.Sleep: I'm quite confident we don't need them and can actually do better. I have made suggestions how to replace all of them, except for one where I'm not totally sure but it looks replaceable too.
CI env var: As outlined, I'm not really in favor of it. It's the least important point to me, though.

timoreimann · 2017-05-16T00:13:22Z

integration/healthcheck_test.go

+	}
+
+	// Waiting for Traefik healthcheck
+	try.Sleep(2 * time.Second)


We should be able to drop this one if we just increase the timeout in line 65 a bit.

I deleted all sleep except this one and refactor the whole test.

timoreimann · 2017-05-16T00:30:56Z

integration/healthcheck_test.go

-	time.Sleep(time.Second * 3)
-
-	resp, err = client.Do(req)
+	// Verify frontend health : before


I think the remaining block up until line 89 can be simplified as following:

Try-request for a 200 response code. Once we succeed, we know for sure that the first whoami host has successfully toggled its health status back to 200. Also, this way we don't have to rely on the try.Sleep in line 79.

Try-request for a 500 response code. This verifies that the second whoami host is still unhealthy.

Paraphrased, we can remove the section between line 74 and line 80.

emilevauge

Wow, this PR is so amazing @ldez
LGTM 👏 👏 👏

emilevauge · 2017-05-15T15:51:57Z

integration/acme_test.go

-		return nil
-	})
-
+	err := try.GetRequest("http://"+s.boulderIP+":4000/directory", 120*time.Second, try.StatusCodeIs(200))


sed/200/http.StatusOK eventually ?

emilevauge · 2017-05-15T16:01:05Z

integration/constraint_test.go

+
+		return nil
+	})
+	c.Assert(err, checker.IsNil)


(Note that this is the reason why I think try.Do(t, 3*time.Second, …) would fit perfectly. But can be done in follow-ups.

emilevauge · 2017-05-17T10:01:29Z

integration/eureka_test.go

@@ -66,7 +63,7 @@ func (s *EurekaSuite) TestSimpleConfiguration(c *check.C) {
    }
 	}`

-	tmpl, err := template.New("eurekaTemlate").Parse(eurekaTemplate)
+	tmpl, err := template.New("eurekaTemplate").Parse(eurekaTemplate)


vdemeester

Few small comments, but can definitely merged as is 😎 🎉 👏
LGTM 🦁 (probably not with 54 commits though 😝)

vdemeester · 2017-05-17T12:05:53Z

integration/constraint_test.go

+
+		return nil
+	})
+	c.Assert(err, checker.IsNil)


(Note that this is the reason why I think try.Do(t, 3*time.Second, …) would fit perfectly. But can be done in follow-ups.

vdemeester · 2017-05-17T12:06:39Z

integration/eureka_test.go

@@ -66,7 +63,7 @@ func (s *EurekaSuite) TestSimpleConfiguration(c *check.C) {
    }
 	}`

-	tmpl, err := template.New("eurekaTemlate").Parse(eurekaTemplate)
+	tmpl, err := template.New("eurekaTemplate").Parse(eurekaTemplate)


vdemeester · 2017-05-17T12:09:27Z

integration/try/condition.go

+// ResponseCondition is a retry condition function.
+// It receives a response, and returns an error
+// if the response failed the condition.
+type ResponseCondition func(*http.Response) error


Nit: could be unexported (but lint or vet might be not happy, not sure)

vdemeester · 2017-05-17T12:09:43Z

integration/try/condition.go

+
+// DoCondition is a retry condition function.
+// It returns an error
+type DoCondition func() error


Nit (same as above): could be unexported (but lint or vet might be not happy, not sure)

vdemeester · 2017-05-17T12:10:17Z

integration/try/try.go

+
+	timeout = applyCIMultiplier(timeout)
+
+	var err error


yeah I don't think we need to declare it before hand.

- feat: add CI multiplier - refactor: readability - feat: custom Sleep function - refactor(integration): use custom Sleep - feat: show Try progress - feat(try): try response with status code - refactor(try): use a dedicate package. - refactor(integration): Try everywhere - feat(CI): pass CI env var to Integration Tests. - refactor(acme): increase timeout. - feat(acme): show Traefik logs - refactor(integration): use `http.StatusXXX` - refactor: remove Sleep

timoreimann

@ldez:

ldez added area/provider kind/enhancement a new or improved feature. labels May 13, 2017

ldez requested review from timoreimann and emilevauge May 13, 2017 23:12

ldez added the status/2-needs-review label May 13, 2017

ldez force-pushed the refactor-deflake-integration-tests branch from f4f6c39 to 4c566aa Compare May 14, 2017 01:53

vdemeester suggested changes May 14, 2017

View reviewed changes

vdemeester reviewed May 14, 2017

View reviewed changes

atbore-phx mentioned this pull request May 14, 2017

Flaky integration tests #1600

Closed

ldez force-pushed the refactor-deflake-integration-tests branch from f5cbc19 to c6c98da Compare May 14, 2017 17:10

timoreimann suggested changes May 15, 2017

View reviewed changes

timoreimann suggested changes May 16, 2017

View reviewed changes

timoreimann mentioned this pull request May 16, 2017

[WIP] Deflake integration tests. #1284

Closed

2 tasks

emilevauge approved these changes May 17, 2017

View reviewed changes

vdemeester approved these changes May 17, 2017

View reviewed changes

ldez force-pushed the refactor-deflake-integration-tests branch from bd3a0f9 to 2004de6 Compare May 17, 2017 13:23

ldez force-pushed the refactor-deflake-integration-tests branch from 2004de6 to 59a48fe Compare May 17, 2017 14:34

timoreimann approved these changes May 18, 2017

View reviewed changes

ldez added status/3-needs-merge and removed status/2-needs-review labels May 18, 2017

ldez added this to the 1.4 milestone May 18, 2017

ldez merged commit 2610023 into traefik:master May 18, 2017

ldez deleted the refactor-deflake-integration-tests branch May 18, 2017 20:34

ldez removed the status/3-needs-merge label May 19, 2017

ldez mentioned this pull request Jun 9, 2017

Replace fixed readiness timeouts in docker-compose fixture setups by retry-based readiness checks #1267

Closed


		_, err = ioutil.ReadAll(resp.Body)
		err = try.Request(req, 5*time.Second, try.StatusCodeIs(200), try.BodyContains("Welcome to nginx!"))

Deflake integration tests #1599

Deflake integration tests #1599

Conversation

ldez commented May 13, 2017

Description

vdemeester left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

vdemeester May 14, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

atbore-phx May 14, 2017 • edited Loading

Choose a reason for hiding this comment

atbore-phx May 14, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ldez May 14, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

atbore-phx commented May 14, 2017 • edited Loading

ldez commented May 14, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

timoreimann May 15, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

timoreimann left a comment • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

emilevauge left a comment • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

vdemeester left a comment • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

timoreimann left a comment

Choose a reason for hiding this comment

vdemeester May 14, 2017 •

edited

Loading

atbore-phx May 14, 2017 •

edited

Loading

atbore-phx May 14, 2017 •

edited

Loading

ldez May 14, 2017 •

edited

Loading

atbore-phx commented May 14, 2017 •

edited

Loading

timoreimann May 15, 2017 •

edited

Loading

timoreimann left a comment •

edited

Loading

emilevauge left a comment •

edited

Loading

vdemeester left a comment •

edited

Loading