search

hashicorp / terraform-provider-aws

The AWS Provider enables Terraform to manage AWS resources.
https://registry.terraform.io/providers/hashicorp/aws
Mozilla Public License 2.0
9.84k stars 9.19k forks source link

aws_s3_bucket_object inconsistently returning "Provider produced inconsistent result after apply" #9725

Closed alpacamybags118 closed 3 years ago

alpacamybags118 commented 5 years ago

Community Note

Terraform Version

0.12.6

Affected Resource(s)

Terraform Configuration Files

resource "aws_s3_bucket_object" "test" {
  bucket       = var.website_domain_name
  key          = "image.png"
  source       = "${path.module}/../example-website/image.png"
  etag         = filemd5("${path.module}/../example-website/image.png")
  content_type = "image/png"
}

Debug Output

Panic Output

Expected Behavior

An object was added to the bucket.

Actual Behavior

Error: Provider produced inconsistent result after apply
When applying changes to aws_s3_bucket_object.test, provider "aws" produced an unexpected new value for was present, but now absent. This is a bug in the provider, which should be reported in the provider's own
issue tracker.

Steps to Reproduce

  1. Setup an environment with a png file to upload
  2. terraform apply

Important Factoids

References

nywilken commented 5 years ago

hi @alpacamybags118 sorry you are running into issues here, and we appreciate you opening up an issue. Do you know if any of the tests being executed are modifying the same resource?

There are a number of computed properties on this resource so it might be possible that actual state is changing between parallel test runs. That's a first guess. Unfortunately, without any debug logs there is not much that can be identified here as the issue is not reproducible on it's own.

If this is something that is effecting your infrastructure deployment can you please update this issue with the relevant debug log information - see Terraform Debugging - so that we can dive deeper into the provided error.

Cheers!

alpacamybags118 commented 5 years ago

@nywilken i was able to get a debug log - what's the best way to get it to you guys?

something i was thinking about - while there isn't anything executing on the same resource, a few of the tasks are adding an object to a bucket (the same file). Maybe its possible that one of the tests has a lock on the file at the same time as another test is trying to read it?

alpacamybags118 commented 5 years ago

@nywilken in the meantime, i was looking through the logs and I think this piece might be of use ivateExample 2019-08-21T04:39:06Z command.go:158: 2019/08/21 04:39:06 [WARN] Provider "aws" produced an unexpected new value for aws_s3_bucket_object.grunty, but we are tolerating it because it is using the legacy plugin SDK. TestCloudFrontS3OriginGroup/TestCloudFrontOriginGroupS3PrivateExample 2019-08-21T04:39:06Z command.go:158: The following problems may be the cause of any confusing errors from downstream operations: TestCloudFrontS3OriginGroup/TestCloudFrontOriginGroupS3PrivateExample 2019-08-21T04:39:06Z command.go:158: - .content_disposition: was null, but now cty.StringVal("") TestCloudFrontS3OriginGroup/TestCloudFrontOriginGroupS3PrivateExample 2019-08-21T04:39:06Z command.go:158: - .website_redirect: was null, but now cty.StringVal("") TestCloudFrontS3OriginGroup/TestCloudFrontOriginGroupS3PrivateExample 2019-08-21T04:39:06Z command.go:158: - .content_language: was null, but now cty.StringVal("") TestCloudFrontS3OriginGroup/TestCloudFrontOriginGroupS3PrivateExample 2019-08-21T04:39:06Z command.go:158: - .content_encoding: was null, but now cty.StringVal("") TestCloudFrontS3OriginGroup/TestCloudFrontOriginGroupS3PrivateExample 2019-08-21T04:39:06Z command.go:158: - .cache_control: was null, but now cty.StringVal("") TestCloudFrontS3OriginGroup/TestCloudFrontOriginGroupS3PrivateExample 2019-08-21T04:39:06Z command.go:158: 2019/08/21 04:39:06 [TRACE] <root>: eval: *terraform.EvalMaybeTainted TestCloudFrontS3OriginGroup/TestCloudFrontOriginGroupS3PrivateExample 2019-08-21T04:39:06Z command.go:158: 2019/08/21 04:39:06 [TRACE] <root>: eval: *terraform.EvalWriteState TestCloudFrontS3OriginGroup/TestCloudFrontOriginGroupS3PrivateExample 2019-08-21T04:39:06Z command.go:158: aws_s3_bucket_object.grunty: Creation complete after 1s [id=grunty.png] TestCloudFrontS3OriginGroup/TestCloudFrontOriginGroupS3PrivateExample 2019-08-21T04:39:06Z command.go:158: TestCloudFrontS3OriginGroup/TestCloudFrontOriginGroupS3PrivateExample 2019-08-21T04:39:06Z command.go:158: Error: Provider produced inconsistent result after apply TestCloudFrontS3OriginGroup/TestCloudFrontOriginGroupS3PrivateExample 2019-08-21T04:39:06Z command.go:158: TestCloudFrontS3OriginGroup/TestCloudFrontOriginGroupS3PrivateExample 2019-08-21T04:39:06Z command.go:158: When applying changes to aws_s3_bucket_object.index, provider "aws" produced TestCloudFrontS3OriginGroup/TestCloudFrontOriginGroupS3PrivateExample 2019-08-21T04:39:06Z command.go:158: an unexpected new value for was present, but now absent. TestCloudFrontS3OriginGroup/TestCloudFrontOriginGroupS3PrivateExample 2019-08-21T04:39:06Z command.go:158: TestCloudFrontS3OriginGroup/TestCloudFrontOriginGroupS3PrivateExample 2019-08-21T04:39:06Z command.go:158: This is a bug in the provider, which should be reported in the provider's own TestCloudFrontS3OriginGroup/TestCloudFrontOriginGroupS3PrivateExample 2019-08-21T04:39:06Z command.go:158: issue tracker.

Something interesting to note is the object this is uploading is a PNG file, which other calls to this resource that I'm using are upload .HTML files and seem to work fine.

alpacamybags118 commented 5 years ago

@nywilken as an update to those errors, I was able to get around them by adding the following lines to my s3 object resources:

 content_disposition = ""
 website_redirect = ""
 content_language = ""
 content_encoding = ""
 cache_control = ""

The provider "aws" produced an unexpected new value for was present, but now absent error is still an issue, though.

Here are some relevant logs that might help (omitting anything that could be sensitive:

TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: 2019-08-22T10:38:49.882Z [DEBUG] plugin.terraform-provider-aws_v2.24.0_x4: 2019/08/22 10:38:49 [DEBUG] [aws-sdk-go] DEBUG: Response s3/PutObject Details:
TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: 2019-08-22T10:38:49.882Z [DEBUG] plugin.terraform-provider-aws_v2.24.0_x4: ---[ RESPONSE ]--------------------------------------
TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: 2019-08-22T10:38:49.882Z [DEBUG] plugin.terraform-provider-aws_v2.24.0_x4: HTTP/1.1 200 OK
TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: 2019-08-22T10:38:49.882Z [DEBUG] plugin.terraform-provider-aws_v2.24.0_x4: Connection: close
TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: 2019-08-22T10:38:49.882Z [DEBUG] plugin.terraform-provider-aws_v2.24.0_x4: Content-Length: 0
TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: 2019-08-22T10:38:49.882Z [DEBUG] plugin.terraform-provider-aws_v2.24.0_x4: Date: Thu, 22 Aug 2019 10:38:50 GMT
TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: 2019-08-22T10:38:49.882Z [DEBUG] plugin.terraform-provider-aws_v2.24.0_x4: Etag: "577eed03a2ffc412d4a0241880457e9e"
TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: 2019-08-22T10:38:49.882Z [DEBUG] plugin.terraform-provider-aws_v2.24.0_x4: Server: AmazonS3
TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: 2019-08-22T10:38:49.882Z [DEBUG] plugin.terraform-provider-aws_v2.24.0_x4: X-Amz-Id-2: 3y9yZqm/5N0dlMAutbMn0xNVuAzjXNcUECONd2UVHf3eUS4h4xcJJ+vh2vKPD000HhoxWmNuevI=
TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: 2019-08-22T10:38:49.882Z [DEBUG] plugin.terraform-provider-aws_v2.24.0_x4: X-Amz-Request-Id: 58C0D721831FC4F7
TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: 2019-08-22T10:38:49.882Z [DEBUG] plugin.terraform-provider-aws_v2.24.0_x4: X-Amz-Server-Side-Encryption: AES256
TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: 2019-08-22T10:38:49.882Z [DEBUG] plugin.terraform-provider-aws_v2.24.0_x4: X-Amz-Version-Id: MUKV7JtTb4SRWJldTHn4wL8Zjger1CIa
TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: 2019-08-22T10:38:49.882Z [DEBUG] plugin.terraform-provider-aws_v2.24.0_x4: 
TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: 2019-08-22T10:38:49.882Z [DEBUG] plugin.terraform-provider-aws_v2.24.0_x4: 
TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: 2019-08-22T10:38:49.882Z [DEBUG] plugin.terraform-provider-aws_v2.24.0_x4: -----------------------------------------------------
TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: 2019-08-22T10:38:49.882Z [DEBUG] plugin.terraform-provider-aws_v2.24.0_x4: 2019/08/22 10:38:49 [DEBUG] [aws-sdk-go] 
TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: 2019-08-22T10:38:49.882Z [DEBUG] plugin.terraform-provider-aws_v2.24.0_x4: 2019/08/22 10:38:49 [DEBUG] [aws-sdk-go] DEBUG: Request s3/HeadObject Details:
TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: 2019-08-22T10:38:49.882Z [DEBUG] plugin.terraform-provider-aws_v2.24.0_x4: ---[ REQUEST POST-SIGN ]-----------------------------
TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: 2019-08-22T10:38:49.882Z [DEBUG] plugin.terraform-provider-aws_v2.24.0_x4: HEAD /cloudfront-example-uwl9up.gruntwork.in/grunty.png HTTP/1.1
TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: 2019-08-22T10:38:49.882Z [DEBUG] plugin.terraform-provider-aws_v2.24.0_x4: Host: s3.amazonaws.com
TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: 2019-08-22T10:38:49.882Z [DEBUG] plugin.terraform-provider-aws_v2.24.0_x4: User-Agent: aws-sdk-go/1.23.0 (go1.12.6; linux; amd64) APN/1.0 HashiCorp/1.0 Terraform/0.12.6
TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: 2019-08-22T10:38:49.882Z [DEBUG] plugin.terraform-provider-aws_v2.24.0_x4: Authorization: AWS4-HMAC-SHA256 Credential=***, SignedHeaders=host;x-amz-content-sha256;x-amz-date, Signature=***
TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: 2019-08-22T10:38:49.882Z [DEBUG] plugin.terraform-provider-aws_v2.24.0_x4: X-Amz-Content-Sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: 2019-08-22T10:38:49.882Z [DEBUG] plugin.terraform-provider-aws_v2.24.0_x4: X-Amz-Date: 20190822T103849Z
TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: 2019-08-22T10:38:49.882Z [DEBUG] plugin.terraform-provider-aws_v2.24.0_x4: 
TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: 2019-08-22T10:38:49.882Z [DEBUG] plugin.terraform-provider-aws_v2.24.0_x4: 
TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: 2019-08-22T10:38:49.882Z [DEBUG] plugin.terraform-provider-aws_v2.24.0_x4: -----------------------------------------------------
TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: 2019-08-22T10:38:49.898Z [DEBUG] plugin.terraform-provider-aws_v2.24.0_x4: 2019/08/22 10:38:49 [DEBUG] [aws-sdk-go] DEBUG: Response s3/HeadObject Details:
TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: 2019-08-22T10:38:49.898Z [DEBUG] plugin.terraform-provider-aws_v2.24.0_x4: ---[ RESPONSE ]--------------------------------------
TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: 2019-08-22T10:38:49.898Z [DEBUG] plugin.terraform-provider-aws_v2.24.0_x4: HTTP/1.1 404 Not Found
TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: 2019-08-22T10:38:49.898Z [DEBUG] plugin.terraform-provider-aws_v2.24.0_x4: Connection: close
TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: 2019-08-22T10:38:49.898Z [DEBUG] plugin.terraform-provider-aws_v2.24.0_x4: Transfer-Encoding: chunked
TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: 2019-08-22T10:38:49.898Z [DEBUG] plugin.terraform-provider-aws_v2.24.0_x4: Content-Type: application/xml
TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: 2019-08-22T10:38:49.898Z [DEBUG] plugin.terraform-provider-aws_v2.24.0_x4: Date: Thu, 22 Aug 2019 10:38:49 GMT
TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: 2019-08-22T10:38:49.898Z [DEBUG] plugin.terraform-provider-aws_v2.24.0_x4: Server: AmazonS3
TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: 2019-08-22T10:38:49.898Z [DEBUG] plugin.terraform-provider-aws_v2.24.0_x4: X-Amz-Id-2: BnyexsfizuxdaaxMXVnZxjTmWTcwtcwHVcFYdu8lg5/54EDBrpvvd5UlO8NKuVGp4YTJeIe7EwU=
TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: 2019-08-22T10:38:49.898Z [DEBUG] plugin.terraform-provider-aws_v2.24.0_x4: X-Amz-Request-Id: 0B73F2E9C91238A9
TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: 2019-08-22T10:38:49.898Z [DEBUG] plugin.terraform-provider-aws_v2.24.0_x4: 
TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: 2019-08-22T10:38:49.898Z [DEBUG] plugin.terraform-provider-aws_v2.24.0_x4: 
TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: 2019-08-22T10:38:49.898Z [DEBUG] plugin.terraform-provider-aws_v2.24.0_x4: 
TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: 2019-08-22T10:38:49.898Z [DEBUG] plugin.terraform-provider-aws_v2.24.0_x4: -----------------------------------------------------
TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: 2019-08-22T10:38:49.898Z [DEBUG] plugin.terraform-provider-aws_v2.24.0_x4: 2019/08/22 10:38:49 [DEBUG] [aws-sdk-go] 
TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: 2019-08-22T10:38:49.898Z [DEBUG] plugin.terraform-provider-aws_v2.24.0_x4: 2019/08/22 10:38:49 [DEBUG] [aws-sdk-go] DEBUG: Validate Response s3/HeadObject failed, attempt 0/25, error NotFound: Not Found
TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: 2019-08-22T10:38:49.898Z [DEBUG] plugin.terraform-provider-aws_v2.24.0_x4:     status code: 404, request id: 0B73F2E9C91238A9, host id: BnyexsfizuxdaaxMXVnZxjTmWTcwtcwHVcFYdu8lg5/54EDBrpvvd5UlO8NKuVGp4YTJeIe7EwU=
TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: 2019-08-22T10:38:49.898Z [DEBUG] plugin.terraform-provider-aws_v2.24.0_x4: 2019/08/22 10:38:49 [WARN] Error Reading Object (grunty.png), object not found (HTTP status 404)
TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: 2019/08/22 10:38:49 [DEBUG] aws_s3_bucket_object.grunty: apply errored, but we're indicating that via the Error pointer rather than returning it: Provider produced inconsistent result after apply: When applying changes to aws_s3_bucket_object.grunty, provider "aws" produced an unexpected new value for was present, but now absent.
TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: 
TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: This is a bug in the provider, which should be reported in the provider's own issue tracker.
TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: 2019/08/22 10:38:49 [TRACE] <root>: eval: *terraform.EvalMaybeTainted
TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: 2019/08/22 10:38:49 [ERROR] <root>: eval: *terraform.EvalApplyPost, err: Provider produced inconsistent result after apply: When applying changes to aws_s3_bucket_object.grunty, provider "aws" produced an unexpected new value for was present, but now absent.
TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: 
TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: This is a bug in the provider, which should be reported in the provider's own issue tracker.
TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: 2019/08/22 10:38:49 [ERROR] <root>: eval: *terraform.EvalSequence, err: Provider produced inconsistent result after apply: When applying changes to aws_s3_bucket_object.grunty, provider "aws" produced an unexpected new value for was present, but now absent.
TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: 
TestCloudFrontS3/TestCloudFrontS3PrivateExample 2019-08-22T10:38:49Z command.go:158: This is a bug in the provider, which should be reported in the provider's own issue tracker.

The etag 577eed03a2ffc412d4a0241880457e9e is the md5 of the PNG file that it is referring to as missing.

wking commented 5 years ago

We hit this too, and Terraform debug logs for our case are here. I'll check our CloudTrail logs for possible parallel activity later today.

wking commented 5 years ago

So trigger in our job seems to have been:

time="2019-08-22T12:53:41Z" level=debug msg="2019-08-22T12:53:41.704Z [DEBUG] plugin.terraform-provider-aws: 2019/08/22 12:53:41 [DEBUG] Trying to create new S3 bucket: \"terraform-20190822125341704600000001\""
time="2019-08-22T12:53:41Z" level=debug msg="2019-08-22T12:53:41.705Z [DEBUG] plugin.terraform-provider-aws: 2019/08/22 12:53:41 [DEBUG] [aws-sdk-go] DEBUG: Request s3/CreateBucket Details:"
...
time="2019-08-22T12:53:42Z" level=debug msg="2019-08-22T12:53:42.168Z [DEBUG] plugin.terraform-provider-aws: 2019/08/22 12:53:42 [DEBUG] [aws-sdk-go] DEBUG: Response s3/CreateBucket Details:"
time="2019-08-22T12:53:42Z" level=debug msg="2019-08-22T12:53:42.168Z [DEBUG] plugin.terraform-provider-aws: ---[ RESPONSE ]--------------------------------------"
time="2019-08-22T12:53:42Z" level=debug msg="2019-08-22T12:53:42.168Z [DEBUG] plugin.terraform-provider-aws: HTTP/1.1 200 OK"
...
time="2019-08-22T12:53:42Z" level=debug msg="2019-08-22T12:53:42.396Z [DEBUG] plugin.terraform-provider-aws: 2019/08/22 12:53:42 [DEBUG] [aws-sdk-go] DEBUG: Response s3/PutBucketTagging Details:"
time="2019-08-22T12:53:42Z" level=debug msg="2019-08-22T12:53:42.396Z [DEBUG] plugin.terraform-provider-aws: ---[ RESPONSE ]--------------------------------------"
time="2019-08-22T12:53:42Z" level=debug msg="2019-08-22T12:53:42.396Z [DEBUG] plugin.terraform-provider-aws: HTTP/1.1 204 No Content"
...
time="2019-08-22T12:53:42Z" level=debug msg="2019-08-22T12:53:42.462Z [DEBUG] plugin.terraform-provider-aws: 2019/08/22 12:53:42 [DEBUG] [aws-sdk-go] DEBUG: Response s3/HeadBucket Details:"
time="2019-08-22T12:53:42Z" level=debug msg="2019-08-22T12:53:42.462Z [DEBUG] plugin.terraform-provider-aws: ---[ RESPONSE ]--------------------------------------"
time="2019-08-22T12:53:42Z" level=debug msg="2019-08-22T12:53:42.462Z [DEBUG] plugin.terraform-provider-aws: HTTP/1.1 404 Not Found"

Checking our logs with:

SELECT eventtime,
    eventname,
    useridentity.username,
    useragent,
    requestparameters
    errorcode,
    errormessage
FROM "default"."cloudtrail_logs"
WHERE from_iso8601_timestamp(eventtime) > from_iso8601_timestamp('2019-08-22T12:53:40Z')
  AND from_iso8601_timestamp(eventtime) < from_iso8601_timestamp('2019-08-22T12:53:43Z')
  AND eventname LIKE '%Bucket'
ORDER BY eventtime;

Gave:

"eventtime","eventname","username","useragent","errorcode","errormessage"
"2019-08-22T12:53:42Z","CreateBucket","origin-ci-robot-provision","[aws-sdk-go/1.19.26 (go1.10.8; linux; amd64) APN/1.0 HashiCorp/1.0 Terraform/0.12.0-rc1]","{""x-amz-acl"":[""private""],""host"":[""terraform-20190822125341704600000001.s3.amazonaws.com""],""bucketName"":""terraform-20190822125341704600000001""}",

So I dunno why the HeadBucket call failed. Later in our CloudTrail logs (via a separate query):

"eventtime","eventname","username","useragent","errorcode","errormessage"
"2019-08-22T13:01:41Z","DeleteBucket","origin-ci-robot-provision","[aws-sdk-go/1.16.14 (go1.10.8; linux; amd64) OpenShift/4.x Installer/unreleased-master-1621-g1f939d01fc96469c2f2205d9e71d6324b85b8a69-dirty OpenShift/4.x Destroyer/unreleased-master-1621-g1f939d01fc96469c2f2205d9e71d6324b85b8a69-dirty]","{""host"":[""terraform-20190822125341704600000001.s3.amazonaws.com""],""bucketName"":""terraform-20190822125341704600000001""}",

And that's well after the failed HeadBucket. Maybe some kind of eventual-consistency AWS thing?

wking commented 5 years ago

Michael B. at AWS got back to me confirming eventual-consistency:

The create bucket request and the time between the put and head request is only about 1 second. The create bucket request needs to propogate to all of S3 hosts. Now i see that because the PUT tag request succeeded but the head at the same time did not, this can be quite strange. However, s3 has many layers and a complex architecture. After checking the requests, it suggests that the create bucket request had not propagated completely to all of S3 and the HEAD request hit a node which the create bucket requested had not fully propagated to.

This section of the documentation outlines the S3 eventual consistency model in detail1.

Because i see the create and head requests within 1 second apart, and s3 provides eventual consistency 1, i would suggest allowing a some more time before the GET or HEAD request, that follow a create or PUT object request.

I'm following up with AWS, because the referenced docs talk about objects in buckets, and not about buckets themselves. And from my reading, they say that you should expect consistent read-after-write for creating PUTs that had no earlier HEAD or GET (which is what we had here) and you only get eventually-consistent read-after-write if you had a leading HEAD or GET.

But however the AWS discussion works out (buggy docs or a buggy implementation), the Terraform provider should probably adjust to gracefully handle the current measured behavior by retrying 404ing HEADs a few times (a minute? I dunno what "some more time" actually means) before erroring out with "inconsistent result after apply". I haven't looked at the backing provider code yet to see what this would entail or how easy it would be to implement.

wking commented 5 years ago

I'm following up with AWS...

John-Michael J. at AWS confirmed that all bucket creation is eventually-consistent read-after-write. There is no bucket-creation case in which they guarantee consistent read-after-write. This contrasts with objects in buckets, where under some conditions they do guarantee consistent read-after-write.

eedwards-sk commented 5 years ago

I just ran into this same issue. It was after going from one object with an md5 based etag haproxy.cfg to multiple objects using foreach, (haproxy.cfg and some others)

It appears the delete/create of haproxy.cfg spurred the error

Error: Provider produced inconsistent result after apply

When applying changes to
module.webrouter_cluster.aws_s3_bucket_object.haproxy_config_files["haproxy.cfg"],
provider "aws" produced an unexpected new value for was present, but now
absent.
eedwards-sk commented 5 years ago

I'm now getting this regularly when updating s3 objects.

It seems to have started once switching to using for_each with a set.

resource "aws_s3_bucket_object" "haproxy_config_files" {
  for_each = fileset(var.haproxy_config_dir_path, "**")

  key    = "${var.service_configs_bucket_path}/config.d/${each.value}"
  bucket = var.service_configs_bucket_name
  source = "${var.haproxy_config_dir_path}/${each.value}"

  etag = filemd5("${var.haproxy_config_dir_path}/${each.value}")
}

edit: I should mention I'm on terraform 0.12.8 with hashicorp/aws 2.27.0

alpacamybags118 commented 5 years ago

For those dealing with this issue, a workaround I did for the time being is to use a null resource and run aws cli commands to manipulate objects in S3. For example:

resource "null_resource" "do_s3_stuff" {
  provisioner "local-exec" {
    command = "aws s3 {what you want to do here}"
  }
}

You would just need to ensure whatever environment you are running your terraform plan/apply in has the cli configured.

richardgavel commented 4 years ago

Is there any update on this issue, to try and put in a retry mechanism similar to the one put in place for S3 buckets? Pretty sure it's another S3 eventual consistency issue. Not covering this scenario (since it could happen at just about any time), prevents us from using the s3_bucket_object resource at all.

https://github.com/terraform-providers/terraform-provider-aws/pull/11894/files

shuheiktgw commented 3 years ago

I've encountered the same problem so I fixed it. Please upvote the PR for a faster review! 🙏

ghost commented 3 years ago

I'm going to lock this issue because it has been closed for 30 days ⏳. This helps our maintainers find and focus on the active issues.

If you feel this issue should be reopened, we encourage creating a new issue linking back to this one for added context. Thanks!