Polling causes SignatureDoesNotMatch error

[akupila]

Confirm by changing [ ] to [x] below to ensure that it's a bug:

• I've gone though the API reference
• I've checked AWS Forums and StackOverflow for answers
• I've searched for previous similar issues and didn't find any solution

Describe the bug
In a polling scenario, a repeated request may return the following error:

SignatureDoesNotMatch: The request signature we calculated does not match the signature you provided. Check your AWS Secret Access Key and signing method. Consult the service documentation for details.

The request that fails is identical to a request that previously succeeded. See below for code.

Version of AWS SDK for Go?
v0.20.0. This does not happen with v0.19.0

Version of Go (go version)?
go version go1.14.1 linux/amd64

To Reproduce (observed behavior)

package main

import (
	"context"
	"flag"
	"fmt"
	"log"
	"os"
	"time"

	"github.com/aws/aws-sdk-go-v2/aws"
	"github.com/aws/aws-sdk-go-v2/aws/external"
	"github.com/aws/aws-sdk-go-v2/service/cloudformation"
)

func main() {
	stack := flag.String("stack", "", "Stack name")
	wait := flag.Duration("wait", 100*time.Millisecond, "Poll wait time")
	flag.Parse()

	if *stack == "" {
		flag.Usage()
		os.Exit(2)
	}

	log.SetFlags(log.Lmicroseconds)

	if err := run(*stack, *wait); err != nil {
		fmt.Fprintln(os.Stderr, err)
		os.Exit(1)
	}
}

func run(stackName string, wait time.Duration) error {
	cfg, err := external.LoadDefaultAWSConfig()
	if err != nil {
		return fmt.Errorf("load aws config: %v", err)
	}
	cf := cloudformation.New(cfg)

	n := 100
	for i := 0; i < n; i++ {
		log.Printf("Request %d", i)
		t := time.Now()
		req := cf.DescribeStackEventsRequest(&cloudformation.DescribeStackEventsInput{
			StackName: aws.String(stackName),
		})
		_, err := req.Send(context.TODO())
		if err != nil {
			return fmt.Errorf("describe stack events: %v", err)
		}
		log.Printf("Completed in %s", time.Since(t))
		time.Sleep(wait)
	}

	return nil
}

$ go run . -stack <valid cloudformation stack>

After ~18 requests, this returns an error with v0.20.0 but all 100 requests succeed on v0.19.0.

Expected behavior
The code above should work the same as in v0.19.0, no error should be returned.

Additional context
I'm not sure if CloudFormation is significant here (that's how i encountered this). As changes to signing and retries were done in v0.20.0 and the issue only appears after some time, i'm guessing the server throttles the request, which causes the client to retry, but the retry doesn't doesn't create the correct signature. Changing the wait time to longer than the default 100ms also allows the code above to run on v0.20.0, which further supports the theory that this is rate limiting/retry related.

[akupila]

Enabling logging (cfg.LogLevel = aws.LogDebug) shows that the request in v0.20.0 has more signed headers

v0.19.0

2020/04/02 11:40:47 DEBUG: Request AWS CloudFormation/DescribeStackEvents Details:
---[ REQUEST POST-SIGN ]-----------------------------
POST / HTTP/1.1
Host: cloudformation.eu-central-1.amazonaws.com
User-Agent: aws-sdk-go/0.19.0 (go1.14.1; linux; amd64)
Content-Length: 64
Authorization: AWS4-HMAC-SHA256 Credential=AKIAICHWxxxxxxxxxxxx/20200402/eu-central-1/cloudformation/aws4_request, SignedHeaders=content-length;content-type;host;x-amz-date, Signature=9a5e41bc3cf30e4ea69a34a722a734e3f9cc2816ef33e8c16ecbxxxxxxxxxxxx
Content-Type: application/x-www-form-urlencoded; charset=utf-8
X-Amz-Date: 20200402T094047Z
Accept-Encoding: gzip


-----------------------------------------------------
2020/04/02 11:40:47 DEBUG: Response AWS CloudFormation/DescribeStackEvents Details:
---[ RESPONSE ]--------------------------------------
HTTP/1.1 200 OK
Transfer-Encoding: chunked
Content-Type: text/xml
Date: Thu, 02 Apr 2020 09:41:19 GMT
Vary: accept-encoding
X-Amzn-Requestid: a7655173-9548-490a-9b11-a0bfe621653c


-----------------------------------------------------

v0.20.0

2020/04/02 11:43:00 DEBUG: Request AWS CloudFormation/DescribeStackEvents Details:
---[ REQUEST POST-SIGN ]-----------------------------
POST / HTTP/1.1
Host: cloudformation.eu-central-1.amazonaws.com
User-Agent: aws-sdk-go/0.20.0 (go1.14.1; linux; amd64)
Content-Length: 64
Amz-Sdk-Invocation-Id: A91B0AA1-5E80-4357-B1E6-D16A84D502A5
Amz-Sdk-Request: attempt=1; max=3
Authorization: AWS4-HMAC-SHA256 Credential=AKIAICHWxxxxxxxxxxxx/20200402/eu-central-1/cloudformation/aws4_request, SignedHeaders=amz-sdk-invocation-id;amz-sdk-request;content-length;content-type;host;x-amz-date, Signature=0728d528338902d1b9e77f19a96473318e3ce7505f6321ff05c0xxxxxxxxxxxx
Content-Type: application/x-www-form-urlencoded; charset=utf-8
X-Amz-Date: 20200402T094300Z
Accept-Encoding: gzip


-----------------------------------------------------
2020/04/02 11:43:00 DEBUG: Response AWS CloudFormation/DescribeStackEvents Details:
---[ RESPONSE ]--------------------------------------
HTTP/1.1 403 Forbidden
Content-Length: 441
Content-Type: text/xml
Date: Thu, 02 Apr 2020 09:43:33 GMT
X-Amzn-Requestid: 1dc1d7ce-4961-41a5-ad74-a58b77a43a5c


-----------------------------------------------------

[dudududi]

I have observed the same issue with v0.20.0, however in my opinion it is not related to wait time between the subsequent requests - it is failing randomly with random clients (not only cfn, I have reproduced it with dynamodb as well)

[dudududi]

Any update on this? In my opinion this makes the v.0.20.0 not usable at all...

[jasdel]

Hi @dudududi thanks for reaching out and letting us know about this issue. We're investigating this issue. This issue and #533 seem to be related to something in the signature getting changed after signing on retries.

We're able to reproduce the issue using the sample code you provided.

[jasdel]

I've created PR #537 that fixes this bug, and allows the SDK to retry failed correctly without signature errors. Once this is merged in we'll include it in our latest release.

[jasdel]

We've released this fix as a tagged released, v0.21.0. You should be able to update to pull in these fixes and updates.