Retry OpenStack requests when throttled

Retry OpenStack requests when throttled

When making a request to OpenStack, it may fail with a 413 if too many requests have been made in a period of time. In such cases, the response headers
will contain a Retry-After value indicating that the client and resend the request after X seconds. This branch enhances the Goose HTTP client to seamlessly
retry the request up to 3 times before it gives up.

Note that other times a 413 may be returned is when a resource limit truly has been exceeded, eg creating a floating ip adress. In this case, the request is not
resent and the call fails immediately.

A fair bit of refactoring in the HTTP client was required to get things in place to allow the request to be retried. I also modified the nova test suite to support
live and local testing so that I could ensure the test double could be made to generate 413s but then found that the nova test double stuff is not quite all landed yet. The
new testing stuff has been left in place though for when everything catches up.

I needed to capture the log output in the new test so added a Logger attribute to the HTTP client. If no logger is passed in, it defaults to the std Go logger.

The retry stuff in this branch fixes some previously broken tests. I modified the remaining broken tests to make them all pass against the live system. 
The only ones that fail now are the floating ip ones and then only if some ip addresses are allocated and left hanging around before the test is run.
We can look to make the tests clean up these perhaps.

https://code.launchpad.net/~wallyworld/goose/rate-limit-retries/+merge/139141

Requires: https://code.launchpad.net/~wallyworld/goose/improved-error-handling/+merge/138394

(do not edit description out of merge proposal)

[wallyworld, 2012-12-11 04:23:07]

Please take a look.

[wallyworld, 2012-12-12 03:32:37]

Please take a look.

[jameinel, 2012-12-12 08:47:26]

I did this review yesterday, but it looks like it didn't get sent properly. So
here are my comments, feel free to discuss it with me.

LGTM. I think all my comments are just comments, not really things that is a
correctness issue.

https://codereview.appspot.com/6920045/diff/1/http/client.go
File http/client.go (right):

https://codereview.appspot.com/6920045/diff/1/http/client.go#newcode53
http/client.go:53: logger = log.New(os.Stderr, "", log.LstdFlags)
Long term, I wonder if we want to just handle the logger being nil, rather than
creating a Stderr logger at this level.
But for now this seems fine.

https://codereview.appspot.com/6920045/diff/1/http/client.go#newcode78
http/client.go:78: headers := make(http.Header)
This is one of those cases where the make vs new distinction is a bit of a
shame. As it looks like you are dealing with a user type (http.Header), but
you're really dealing with a builtin (because type http.Header map[...]).
I sort of wish their interface was just http.NewHeader rather than having you
create it this way.
Nothing for you to change, though. Just an observation.

https://codereview.appspot.com/6920045/diff/1/http/client.go#newcode87
http/client.go:87: headers.Add("Accept", "application/json")
We type "application/json" enough I wonder if a constant would be worthwhile.
(Avoid accidental typos.)

https://codereview.appspot.com/6920045/diff/1/http/client.go#newcode179
http/client.go:179: )
I wonder if we would like to make this an attribute of Client, which we can
eventually make configurable. That way in test suites, or people with
known-flaky connections they could turn it up when necessary, without having
connections hang for a long time when they are going to ultimately fail anyway.
For now, a constant is fine.

https://codereview.appspot.com/6920045/diff/1/http/client.go#newcode196
http/client.go:196: }
This is repeated enough it almost makes me want to have a "copyHeaders(from, to
http.Header)" helper function.

It isn't much code, though.

https://codereview.appspot.com/6920045/diff/1/nova/live_test.go
File nova/live_test.go (right):

https://codereview.appspot.com/6920045/diff/1/nova/live_test.go#newcode21
nova/live_test.go:21: )
Constants like this feel like they should be attributes of the test suite, so we
don't accidentally use them in the wrong places. Though they are 'constants'
which tend to be globally defined.

https://codereview.appspot.com/6920045/diff/1/nova/live_test.go#newcode84
nova/live_test.go:84: c.Assert(sr.Image.Id, Equals, testImageId)
Should these be c.Check? So that you get all the failures in one pass, rather
than Assert and only see the 1 that failed first?

https://codereview.appspot.com/6920045/diff/1/nova/live_test.go#newcode327
nova/live_test.go:327: time.Sleep(10 * time.Second)
Is "GetServer" a POST operation? It seems like a GET to me. Which makes this
throttling incorrect.

Having a test sit idle for many seconds seems quite a waste. Does your retry
logic already handle this?
I feel like we should at least post some sort of "trying again after X seconds"
message if we really are sitting idle for a while. So you can tell that it isn't
just hung, it is just waiting.

This could just be copied code, but it also may be a good time to remove the old
rate limiting since we have the new hotness now. :)

https://codereview.appspot.com/6920045/diff/1/nova/live_test.go#newcode396
nova/live_test.go:396: err = s.nova.DeleteFloatingIP(ip.Id)
Because of the fragility of floating IPs, I wonder if we want to do this more as
a 'defer' from earlier on, or something that we force cleanup in TearDown.
Otherwise if the assertions fail earlier, we'll leak a FloatingIP.

https://codereview.appspot.com/6920045/diff/1/nova/live_test.go#newcode407
nova/live_test.go:407: c.Assert(err, IsNil)
This looks like a place where we might want to test that we can connect to the
Floating IP that we added. We'd need a parameterization of the test to indicate
where there is a real server out there to connect to. Perhaps just a comment at
this point. (But essentially that tests that AddServerFloatingIP actually adds
the IP and we can connect to it.)

https://codereview.appspot.com/6920045/diff/1/nova/live_test.go#newcode452
nova/live_test.go:452: }
I like and don't like this test. It feels a bit like testing by side-effect. It
feels a bit more like something that shouldn't be a live test. But instead we
force our stub server to generate a controlled retry, and ensure that the client
code handles it.
(Imagine you start the test right at the edge of however Openstack tracks the
actual limiting, so it doesn't actually trigger a retry.)

Put another way, I think not having tests spuriously fail is enough for 'live'
testing, and we want more direct testing of the client, we can do it in a more
direct fashion.

(Though we can leave this in for now if you're passionate about it.)

https://codereview.appspot.com/6920045/diff/1/nova/nova.go
File nova/nova.go (right):

https://codereview.appspot.com/6920045/diff/1/nova/nova.go#newcode289
nova/nova.go:289: 
yay. I wonder if the doc should give a hint that this is inefficient to call
lots of times? For now, I think it is better than not having it.

[wallyworld, 2012-12-13 01:59:48]

Please take a look.

https://codereview.appspot.com/6920045/diff/1/http/client.go
File http/client.go (right):

https://codereview.appspot.com/6920045/diff/1/http/client.go#newcode87
http/client.go:87: headers.Add("Accept", "application/json")
On 2012/12/12 08:47:26, jameinel wrote:
> We type "application/json" enough I wonder if a constant would be worthwhile.
> (Avoid accidental typos.)

Done.

https://codereview.appspot.com/6920045/diff/1/http/client.go#newcode179
http/client.go:179: )
On 2012/12/12 08:47:26, jameinel wrote:
> I wonder if we would like to make this an attribute of Client, which we can
> eventually make configurable. That way in test suites, or people with
> known-flaky connections they could turn it up when necessary, without having
> connections hang for a long time when they are going to ultimately fail
anyway.
> For now, a constant is fine.

Done.

https://codereview.appspot.com/6920045/diff/1/http/client.go#newcode196
http/client.go:196: }
On 2012/12/12 08:47:26, jameinel wrote:
> This is repeated enough it almost makes me want to have a "copyHeaders(from,
to
> http.Header)" helper function.
> 
> It isn't much code, though.

I figured it was just a few very simple lines it wasn't worth the effort.

https://codereview.appspot.com/6920045/diff/1/nova/live_test.go
File nova/live_test.go (right):

https://codereview.appspot.com/6920045/diff/1/nova/live_test.go#newcode21
nova/live_test.go:21: )
On 2012/12/12 08:47:26, jameinel wrote:
> Constants like this feel like they should be attributes of the test suite, so
we
> don't accidentally use them in the wrong places. Though they are 'constants'
> which tend to be globally defined.

They aren't exported so I think it's ok to keep them here.

https://codereview.appspot.com/6920045/diff/1/nova/live_test.go#newcode84
nova/live_test.go:84: c.Assert(sr.Image.Id, Equals, testImageId)
On 2012/12/12 08:47:26, jameinel wrote:
> Should these be c.Check? So that you get all the failures in one pass, rather
> than Assert and only see the 1 that failed first?

Yeah, this file was just copied almost verbatim from the original prototype
tests. I've fixed it here and also other places.

https://codereview.appspot.com/6920045/diff/1/nova/live_test.go#newcode327
nova/live_test.go:327: time.Sleep(10 * time.Second)
On 2012/12/12 08:47:26, jameinel wrote:
> Is "GetServer" a POST operation? It seems like a GET to me. Which makes this
> throttling incorrect.
> 
> Having a test sit idle for many seconds seems quite a waste. Does your retry
> logic already handle this?
> I feel like we should at least post some sort of "trying again after X
seconds"
> message if we really are sitting idle for a while. So you can tell that it
isn't
> just hung, it is just waiting.
> 
> This could just be copied code, but it also may be a good time to remove the
old
> rate limiting since we have the new hotness now. :)

This code is polling a newly started server waiting for it to build and then
become active. It uses GET which is not rate limited as far as I can tell
(except for GETs to "changes-since"). So I am assuming the comment about rate
limiting is a mistake. The rate limit retry logic is not relevant here.

I think there needs to be a gap between polls, and thought something like 5
seconds seems more appropriate perhaps. So I tried that and the request returned
an EOF error. Changing it back to 10 seconds fixed it. I'm not 100% sure exactly
what is going on here since we are not getting a 413 back and I can't see in the
docs where an EOF may be returned.

I added a logged message.

https://codereview.appspot.com/6920045/diff/1/nova/live_test.go#newcode396
nova/live_test.go:396: err = s.nova.DeleteFloatingIP(ip.Id)
On 2012/12/12 08:47:26, jameinel wrote:
> Because of the fragility of floating IPs, I wonder if we want to do this more
as
> a 'defer' from earlier on, or something that we force cleanup in TearDown.
> Otherwise if the assertions fail earlier, we'll leak a FloatingIP.

I've used defer.

https://codereview.appspot.com/6920045/diff/1/nova/live_test.go#newcode407
nova/live_test.go:407: c.Assert(err, IsNil)
On 2012/12/12 08:47:26, jameinel wrote:
> This looks like a place where we might want to test that we can connect to the
> Floating IP that we added. We'd need a parameterization of the test to
indicate
> where there is a real server out there to connect to. Perhaps just a comment
at
> this point. (But essentially that tests that AddServerFloatingIP actually adds
> the IP and we can connect to it.)

I've added a TODO for now

https://codereview.appspot.com/6920045/diff/1/nova/live_test.go#newcode452
nova/live_test.go:452: }
On 2012/12/12 08:47:26, jameinel wrote:
> I like and don't like this test. It feels a bit like testing by side-effect.
It
> feels a bit more like something that shouldn't be a live test. But instead we
> force our stub server to generate a controlled retry, and ensure that the
client
> code handles it.
> (Imagine you start the test right at the edge of however Openstack tracks the
> actual limiting, so it doesn't actually trigger a retry.)
> 

I used > 10 POSTS in the for loop to ensure we do always trigger the rate
limiting from the server.

> Put another way, I think not having tests spuriously fail is enough for 'live'
> testing, and we want more direct testing of the client, we can do it in a more
> direct fashion.
> 
> (Though we can leave this in for now if you're passionate about it.)

I agree. It's here now until the nova test double is finished and we add support
for this to the double. I should have added a TODO which I will do.

https://codereview.appspot.com/6920045/diff/1/nova/nova.go
File nova/nova.go (right):

https://codereview.appspot.com/6920045/diff/1/nova/nova.go#newcode289
nova/nova.go:289: 
On 2012/12/12 08:47:26, jameinel wrote:
> yay. I wonder if the doc should give a hint that this is inefficient to call
> lots of times? For now, I think it is better than not having it.
> 

Done.

[jameinel, 2012-12-13 10:05:17]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

...

> 
> https://codereview.appspot.com/6920045/diff/1/nova/live_test.go#newcode21
>
> 
nova/live_test.go:21: )
> On 2012/12/12 08:47:26, jameinel wrote:
>> Constants like this feel like they should be attributes of the
>> test
> suite, so we
>> don't accidentally use them in the wrong places. Though they are
> 'constants'
>> which tend to be globally defined.
> 
> They aren't exported so I think it's ok to keep them here.

They aren't exported, but all variables are accessible in the same
package. Which means it can accidentally get used in real code (and
you wouldn't realize in the test suite, because it is defined there).
Though 'go build' would fail. More importantly "test_foo.go" could
accidentally get "tenantId" from "test_bar.go".

So for now, go with it, but I wanted to highlight my concerns.
...

>> This could just be copied code, but it also may be a good time
>> to
> remove the old
>> rate limiting since we have the new hotness now. :)
> 
> This code is polling a newly started server waiting for it to build
> and then become active. It uses GET which is not rate limited as
> far as I can tell (except for GETs to "changes-since"). So I am
> assuming the comment about rate limiting is a mistake. The rate
> limit retry logic is not relevant here.
> 
> I think there needs to be a gap between polls, and thought
> something like 5 seconds seems more appropriate perhaps. So I tried
> that and the request returned an EOF error. Changing it back to 10
> seconds fixed it. I'm not 100% sure exactly what is going on here
> since we are not getting a 413 back and I can't see in the docs
> where an EOF may be returned.
> 
> I added a logged message.

Thanks. That does seem really strange.

LGTM

John
=:->


-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.12 (Cygwin)
Comment: Using GnuPG with undefined - http://www.enigmail.net/

iEYEARECAAYFAlDJqGcACgkQJdeBCYSNAAM8SACgitD5UeQZmtVGjKKpBPX0t76C
DOIAniQuFSgUD1o8yduBRSN4/y0igO+N
=j2Rw
-----END PGP SIGNATURE-----

[wallyworld, 2012-12-19 07:13:13]

*** Submitted:

Retry OpenStack requests when throttled

When making a request to OpenStack, it may fail with a 413 if too many requests
have been made in a period of time. In such cases, the response headers
will contain a Retry-After value indicating that the client and resend the
request after X seconds. This branch enhances the Goose HTTP client to
seamlessly
retry the request up to 3 times before it gives up.

Note that other times a 413 may be returned is when a resource limit truly has
been exceeded, eg creating a floating ip adress. In this case, the request is
not
resent and the call fails immediately.

A fair bit of refactoring in the HTTP client was required to get things in place
to allow the request to be retried. I also modified the nova test suite to
support
live and local testing so that I could ensure the test double could be made to
generate 413s but then found that the nova test double stuff is not quite all
landed yet. The
new testing stuff has been left in place though for when everything catches up.

I needed to capture the log output in the new test so added a Logger attribute
to the HTTP client. If no logger is passed in, it defaults to the std Go logger.

The retry stuff in this branch fixes some previously broken tests. I modified
the remaining broken tests to make them all pass against the live system. 
The only ones that fail now are the floating ip ones and then only if some ip
addresses are allocated and left hanging around before the test is run.
We can look to make the tests clean up these perhaps.

R=jameinel
CC=
https://codereview.appspot.com/6920045