Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed
alpacamybags118 opened this issue Aug 12, 2019 · 14 comments · Fixed by #17236
Assignees
Labels
bug Addresses a defect in current functionality. service/s3 Issues and PRs that pertain to the s3 service.

Comments

@alpacamybags118
Copy link
Contributor

Community Note

  • Please vote on this issue by adding a 👍 reaction to the original issue to help the community and maintainers prioritize this request
  • Please do not leave "+1" or "me too" comments, they generate extra noise for issue followers and do not help prioritize the request
  • If you are interested in working on this issue or have submitted a pull request, please leave a comment

Terraform Version

0.12.6

Affected Resource(s)

  • aws_aws_s3_bucket_object

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

  • This issue is not consistently happening. It seems to primarily happen when I'm running this resource as part of a larger module, but only when running it in parallel with others as part of a TerraTest test run in a CI pipeline. If I run the test suite locally, it seems to pretty consistently work for me.

References

  • #0000
@ghost ghost added the service/s3 Issues and PRs that pertain to the s3 service. label Aug 12, 2019
@github-actions github-actions bot added the needs-triage Waiting for first response or review from a maintainer. label Aug 12, 2019
@nywilken
Copy link
Member

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!

@nywilken nywilken added waiting-response Maintainers are waiting on response from community or contributor. and removed needs-triage Waiting for first response or review from a maintainer. labels Aug 12, 2019
@alpacamybags118
Copy link
Contributor Author

alpacamybags118 commented Aug 15, 2019

@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?

@ghost ghost removed the waiting-response Maintainers are waiting on response from community or contributor. label Aug 15, 2019
@alpacamybags118
Copy link
Contributor Author

alpacamybags118 commented Aug 21, 2019

@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
Copy link
Contributor Author

@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
Copy link
Contributor

wking commented Aug 22, 2019

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
Copy link
Contributor

wking commented Aug 23, 2019

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
Copy link
Contributor

wking commented Aug 24, 2019

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
Copy link
Contributor

wking commented Aug 27, 2019

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
Copy link

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
Copy link

eedwards-sk commented Sep 7, 2019

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
Copy link
Contributor Author

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
Copy link

richardgavel commented Sep 2, 2020

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
Copy link
Collaborator

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

@bflad bflad added the bug Addresses a defect in current functionality. label Mar 30, 2021
@bflad bflad self-assigned this Mar 30, 2021
@ghost
Copy link

ghost commented Apr 29, 2021

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!

@ghost ghost locked as resolved and limited conversation to collaborators Apr 29, 2021
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
bug Addresses a defect in current functionality. service/s3 Issues and PRs that pertain to the s3 service.
Projects
None yet
7 participants