[Bug]: Inconsistent "Logging: empty output error" with aws_s3_bucket_logging #31139

zack-is-cool · 2023-05-03T16:54:59Z

Terraform Core Version

1.4.4

AWS Provider Version

v4.65.0

Affected Resource(s)

aws_s3_bucket_logging

Expected Behavior

Consistent association between an s3 bucket and an s3 logging bucket.

Actual Behavior

It's inconsistent. Sometimes the bucket logging resource gets created. sometimes terraform throws an error.
see two linked jobs that are running the same code

success:
https:/defenseunicorns/delivery-aws-iac/actions/runs/4873240123/jobs/8692536806#step:15:3046

failure:
https:/defenseunicorns/delivery-aws-iac/actions/runs/4873239923/jobs/8692535048#step:15:3127

Relevant Error/Panic Output Snippet

TestExamplesCompleteInsecure 2023-05-03T14:49:48Z logger.go:66: ╷
TestExamplesCompleteInsecure 2023-05-03T14:49:48Z logger.go:66: │ Error: error reading S3 Bucket (zack-iac-bastion-7d17-sessionlogs-20230503144555996900000003) Logging: empty output
TestExamplesCompleteInsecure 2023-05-03T14:49:48Z logger.go:66: │ 
TestExamplesCompleteInsecure 2023-05-03T14:49:48Z logger.go:66: │   with module.bastion.aws_s3_bucket_logging.access_logging_on_session_logs_bucket,
TestExamplesCompleteInsecure 2023-05-03T14:49:48Z logger.go:66: │   on ../../modules/bastion/s3-buckets.tf line 22, in resource "aws_s3_bucket_logging" "access_logging_on_session_logs_bucket":
TestExamplesCompleteInsecure 2023-05-03T14:49:48Z logger.go:66: │   22: resource "aws_s3_bucket_logging" "access_logging_on_session_logs_bucket" {
TestExamplesCompleteInsecure 2023-05-03T14:49:48Z logger.go:66: │ 
TestExamplesCompleteInsecure 2023-05-03T14:49:48Z logger.go:66: ╵
TestExamplesCompleteInsecure 2023-05-03T14:49:48Z retry.go:99: Returning due to fatal error: FatalError{Underlying: error while running command: exit status 1; ╷
│ Error: error reading S3 Bucket (zack-iac-bastion-7d17-sessionlogs-20230503144555996900000003) Logging: empty output
│ 
│   with module.bastion.aws_s3_bucket_logging.access_logging_on_session_logs_bucket,
│   on ../../modules/bastion/s3-buckets.tf line 22, in resource "aws_s3_bucket_logging" "access_logging_on_session_logs_bucket":
│   22: resource "aws_s3_bucket_logging" "access_logging_on_session_logs_bucket" {
│ 
╵}
    apply.go:15: 
        	Error Trace:	/app/test/e2e/apply.go:15
        	            				/app/test/e2e/examples_complete_insecure_test.go:28
        	            				/app/test/e2e/test_structure.go:28
        	            				/app/test/e2e/examples_complete_insecure_test.go:27
        	            				/app/test/e2e/examples_complete_insecure_test.go:22
        	Error:      	Received unexpected error:
        	            	FatalError{Underlying: error while running command: exit status 1; ╷
        	            	│ Error: error reading S3 Bucket (zack-iac-bastion-7d17-sessionlogs-20230503144555996900000003) Logging: empty output
        	            	│ 
        	            	│   with module.bastion.aws_s3_bucket_logging.access_logging_on_session_logs_bucket,
        	            	│   on ../../modules/bastion/s3-buckets.tf line 22, in resource "aws_s3_bucket_logging" "access_logging_on_session_logs_bucket":
        	            	│   22: resource "aws_s3_bucket_logging" "access_logging_on_session_logs_bucket" {
        	            	│ 
        	            	╵}
        	Test:       	TestExamplesCompleteInsecure

Terraform Configuration Files

https:/defenseunicorns/delivery-aws-iac/blob/bug/fix-s3-bucket-empty-output/examples/complete/fixtures.common.tfvars
https:/defenseunicorns/delivery-aws-iac/blob/bug/fix-s3-bucket-empty-output/examples/complete/fixtures.insecure.tfvars

Steps to Reproduce

Authenticate to AWS
Go to this directory:
https:/defenseunicorns/delivery-aws-iac/tree/bug/fix-s3-bucket-empty-output/examples/complete
run terraform init
run

  terraform apply \
  --auto-approve \
  -var-file fixtures.common.tfvars \
  -var-file fixtures.insecure.tfvars \
  --target='module.vpc' \
  --target='module.bastion'

Debug Output

Big debug

see here:
https:/defenseunicorns/delivery-aws-iac/actions/runs/4875889235/jobs/8698678080#step:15:114362

TestExamplesCompleteInsecure 2023-05-03T19:48:11Z logger.go:66: module.bastion.aws_s3_bucket_logging.access_logging_on_session_logs_bucket: Creating...
TestExamplesCompleteInsecure 2023-05-03T19:48:11Z logger.go:66: 2023-05-03T19:48:11.212Z [INFO]  Starting apply for module.bastion.aws_s3_bucket_logging.access_logging_on_session_logs_bucket
TestExamplesCompleteInsecure 2023-05-03T19:48:11Z logger.go:66: 2023-05-03T19:48:11.212Z [DEBUG] module.bastion.aws_s3_bucket_logging.access_logging_on_session_logs_bucket: applying the planned Create change
TestExamplesCompleteInsecure 2023-05-03T19:48:11Z logger.go:66: 2023-05-03T19:48:11.214Z [DEBUG] provider.terraform-provider-aws_v4.65.0_x5: [DEBUG] Waiting for state to become: [success]

...

TestExamplesCompleteInsecure 2023-05-03T19:48:11Z logger.go:66: 2023-05-03T19:48:11.215Z [DEBUG] provider.terraform-provider-aws_v4.65.0_x5: HTTP Request Sent: http.request.header.authorization="AWS4-HMAC-SHA256 Credential=ASIA************WO53/20230503/us-east-1/s3/aws4_request, SignedHeaders=content-length;content-md5;host;x-amz-content-sha256;x-amz-date;x-amz-security-token, Signature=*****" http.user_agent="APN/1.0 HashiCorp/1.0 Terraform/1.4.4 (+https://www.terraform.io) terraform-provider-aws/4.65.0 (+https://registry.terraform.io/providers/hashicorp/aws) aws-sdk-go/1.44.251 (go1.19.8; linux; amd64)" tf_rpc=ApplyResourceChange @caller=github.com/hashicorp/aws-sdk-go-base/v2/awsv1shim/[email protected]/logger.go:90 @module=aws http.request.body="<BucketLoggingStatus xmlns="http://s3.amazonaws.com/doc/2006-03-01/"><LoggingEnabled><TargetBucket>zack-iac-accesslog-0fb620230503194551153300000004</TargetBucket><TargetPrefix>bastion-session-logs/</TargetPrefix></LoggingEnabled></BucketLoggingStatus>" aws.region=us-east-1 aws.sdk=aws-sdk-go http.request_content_length=252 tf_mux_provider=*schema.GRPCProviderServer tf_req_id=6deae37a-37ed-9e45-900f-c5aa4f105809 net.peer.name=zack-iac-bastion-0fb6-sessionlogs-20230503194551134300000001.s3.amazonaws.com tf_provider_addr=registry.terraform.io/hashicorp/aws tf_resource_type=aws_s3_bucket_logging aws.operation=PutBucketLogging http.flavor=1.1 http.request.header.content_md5=PpcWhO4d6CUuHiPrTToUHg== http.request.header.x_amz_security_token=***** http.url=https://zack-iac-bastion-0fb6-sessionlogs-20230503194551134300000001.s3.amazonaws.com/?logging= aws.service=S3 http.method=PUT http.request.header.x_amz_content_sha256=0689d6645d4585101003fcfc86f6d0c707fff64f738c540a3837e3f2bcbbae36 http.request.header.x_amz_date=20230503T194811Z timestamp=2023-05-03T19:48:11.214Z

...

TestExamplesCompleteInsecure 2023-05-03T19:48:11Z logger.go:66: 2023-05-03T19:48:11.556Z [DEBUG] provider.terraform-provider-aws_v4.65.0_x5: HTTP Response Received: http.response.header.x_amz_request_id=BA9BB5G5R1MKDTH5 tf_mux_provider=*schema.GRPCProviderServer tf_provider_addr=registry.terraform.io/hashicorp/aws tf_resource_type=aws_s3_bucket_logging tf_rpc=ApplyResourceChange @module=aws aws.operation=PutBucketLogging http.response.header.date="Wed, 03 May 2023 19:48:12 GMT" @caller=github.com/hashicorp/aws-sdk-go-base/v2/awsv1shim/[email protected]/logger.go:138 aws.region=us-east-1 http.duration=342 http.response.header.x_amz_id_2=nbJDxt6htkxTxYxsEEweAlzqTM3NODwnuUsO+3elLmL+29doCOz+lkg7k4fEF2L75Jpl11R7Jn0= http.status_code=200 tf_req_id=6deae37a-37ed-9e45-900f-c5aa4f105809 http.response.body= http.response.header.server=AmazonS3 aws.sdk=aws-sdk-go aws.service=S3 timestamp=2023-05-03T19:48:11.556Z
TestExamplesCompleteInsecure 2023-05-03T19:48:11Z logger.go:66: 2023-05-03T19:48:11.557Z [DEBUG] provider.terraform-provider-aws_v4.65.0_x5: [DEBUG] Waiting for state to become: [success]
TestExamplesCompleteInsecure 2023-05-03T19:48:11Z logger.go:66: 2023-05-03T19:48:11.557Z [DEBUG] provider.terraform-provider-aws_v4.65.0_x5: HTTP Request Sent: tf_req_id=6deae37a-37ed-9e45-900f-c5aa4f105809 aws.operation=GetBucketLogging http.flavor=1.1 http.request.header.x_amz_content_sha256=e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 http.request.header.x_amz_date=20230503T194811Z tf_provider_addr=registry.terraform.io/hashicorp/aws http.user_agent="APN/1.0 HashiCorp/1.0 Terraform/1.4.4 (+https://www.terraform.io) terraform-provider-aws/4.65.0 (+https://registry.terraform.io/providers/hashicorp/aws) aws-sdk-go/1.44.251 (go1.19.8; linux; amd64)" tf_rpc=ApplyResourceChange aws.region=us-east-1 aws.sdk=aws-sdk-go aws.service=S3 http.method=GET http.request.header.authorization="AWS4-HMAC-SHA256 Credential=ASIA************WO53/20230503/us-east-1/s3/aws4_request, SignedHeaders=host;x-amz-content-sha256;x-amz-date;x-amz-security-token, Signature=*****" tf_mux_provider=*schema.GRPCProviderServer net.peer.name=zack-iac-bastion-0fb6-sessionlogs-20230503194551134300000001.s3.amazonaws.com tf_resource_type=aws_s3_bucket_logging @caller=github.com/hashicorp/aws-sdk-go-base/v2/awsv1shim/[email protected]/logger.go:90 @module=aws http.request.body= http.request.header.x_amz_security_token=***** http.url=https://zack-iac-bastion-0fb6-sessionlogs-20230503194551134300000001.s3.amazonaws.com/?logging= timestamp=2023-05-03T19:48:11.557Z
TestExamplesCompleteInsecure 2023-05-03T19:48:11Z logger.go:66: 2023-05-03T19:48:11.615Z [DEBUG] provider.terraform-provider-aws_v4.65.0_x5: HTTP Response Received: aws.operation=GetBucketLogging http.response.body="<?xml version="1.0" encoding="UTF-8"?>
TestExamplesCompleteInsecure 2023-05-03T19:48:11Z logger.go:66: 
TestExamplesCompleteInsecure 2023-05-03T19:48:11Z logger.go:66: <BucketLoggingStatus xmlns="http://s3.amazonaws.com/doc/2006-03-01/">
TestExamplesCompleteInsecure 2023-05-03T19:48:11Z logger.go:66:   <!--<LoggingEnabled><TargetBucket>myLogsBucket</TargetBucket><TargetPrefix>add/this/prefix/to/my/log/files/access_log-</TargetPrefix></LoggingEnabled>-->
TestExamplesCompleteInsecure 2023-05-03T19:48:11Z logger.go:66: </BucketLoggingStatus>
TestExamplesCompleteInsecure 2023-05-03T19:48:11Z logger.go:66: " http.response.header.server=AmazonS3 tf_req_id=6deae37a-37ed-9e45-900f-c5aa4f105809 tf_resource_type=aws_s3_bucket_logging aws.region=us-east-1 aws.sdk=aws-sdk-go http.response.header.content_type=application/xml http.response.header.date="Wed, 03 May 2023 19:48:12 GMT" http.response.header.x_amz_id_2=gnGBTYYZjj+qvkZOFyZ12qri4CGs99TufUPdQvZzas6HU67pwBWfvy5sDGh+Als026GgBBNXXsU= http.response_content_length=289 http.status_code=200 @caller=github.com/hashicorp/aws-sdk-go-base/v2/awsv1shim/[email protected]/logger.go:138 tf_provider_addr=registry.terraform.io/hashicorp/aws aws.service=S3 http.response.header.x_amz_request_id=BA90XF01V19MDTB0 http.duration=58 tf_mux_provider=*schema.GRPCProviderServer tf_rpc=ApplyResourceChange @module=aws timestamp=2023-05-03T19:48:11.615Z
Error: mplesCompleteInsecure 2023-05-03T19:48:11Z logger.go:66: 2023-05-03T19:48:11.615Z [ERROR] provider.terraform-provider-aws_v4.65.0_x5: Response contains error diagnostic: diagnostic_detail= diagnostic_summary="error reading S3 Bucket (zack-iac-bastion-0fb6-sessionlogs-20230503194551134300000001) Logging: empty output" tf_proto_version=5.3 tf_provider_addr=registry.terraform.io/hashicorp/aws tf_req_id=6deae37a-37ed-9e45-900f-c5aa4f105809 @caller=github.com/hashicorp/[email protected]/tfprotov5/internal/diag/diagnostics.go:55 tf_resource_type=aws_s3_bucket_logging tf_rpc=ApplyResourceChange @module=sdk.proto diagnostic_severity=ERROR timestamp=2023-05-03T19:48:11.615Z
Error: mplesCompleteInsecure 2023-05-03T19:48:11Z logger.go:66: 2023-05-03T19:48:11.626Z [ERROR] vertex "module.bastion.aws_s3_bucket_logging.access_logging_on_session_logs_bucket" error: error reading S3 Bucket (zack-iac-bastion-0fb6-sessionlogs-20230503194551134300000001) Logging: empty output

And here's a debug output of a success, same pipeline, same code:
https:/defenseunicorns/delivery-aws-iac/actions/runs/4876410873/jobs/8699861176#step:15:35863

Panic Output

No response

Important Factoids

No response

References

Other location where I've seen the error:
https://discuss.hashicorp.com/t/error-error-reading-s3-bucket-logging-empty-output/38854

Don't seem to be having the error with the now deprecated implementation where logging is configured in the aws_s3_bucket resource itself
https://registry.terraform.io/providers/hashicorp/aws/latest/docs/resources/s3_bucket#logging-1

Would you like to implement a fix?

None

The text was updated successfully, but these errors were encountered:

github-actions · 2023-05-03T16:55:12Z

Community Note

Voting for Prioritization

Please vote on this issue by adding a 👍 reaction to the original post to help the community and maintainers prioritize this request.
Please see our prioritization guide for information on how we prioritize.
Please do not leave "+1" or other comments that do not add relevant new information or questions, they generate extra noise for issue followers and do not help prioritize the request.

Volunteering to Work on This Issue

If you are interested in working on this issue, please leave a comment.
If this would be your first contribution, please review the contribution guide.

zack-is-cool · 2023-05-04T17:22:39Z

this looks related:
#30916

nomeelnoj · 2023-05-05T23:34:44Z

Noticing something interesting about this issue. Our CI pipeline runs into this bug on nearly every s3 bucket create, but when we run or debug locally we do not hit it. There is a slight difference in environments:

CI pipeline:

Linux / AMD
Runs terraform plan -out plan.out and then after interactive approval terraform apply plan.out

Local Mac:

Darwin / ARM
Usually just run terraform apply and say yes

I am currently testing this bug on our CI runners and have replicated the issue in the Linux / AMD environment: when we run terraform interactively with terraform apply and then yes, we do not hit the error. However, when we run terraform plan -out plan.out and then terraform apply, we get the same issue. Based on the output, it seems that the order of operations is different between those two--and the bucket logging is created earlier in the plan when using Terraform interactively. Is there a difference to how Terraform walks the dag between terraform apply interactively and terraform apply plan.out? Even isolated to just the Linux / AMD environment, it seems anything other than the interactive approval causes this error. I also tested with terraform apply -auto-approve and even echo "yes" | terraform apply and both yield the logging empty error shows up. The only way I can get it to pass without it is with an interactive apply.

In the output from the terraform apply you can actually see that the order of operations is different between auto-approve and interactive approval, and the bucket logging says "creation complete" much earlier in the interactive approval. Terraform graph is not helpful here unfortunately because I do not know of a way to change the output of that command based on the type of apply command input, but something is definitely different about applying interactively.

I have tried going back to earlier versions of the provider but have not found any that do not have this issue. So far, the only workaround I have found is to do this (which is hacky and gross, but required to unblock our pipeline jobs):

resource "aws_s3_bucket" "default" {
  # ... removed for brevity
}

resource "null_resource" "default" {
  provisioner "local-exec" {
    command = "sleep 15"
  }

  triggers = {
    bucket = aws_s3_bucket.default.bucket
  }

  depends_on = [aws_s3_bucket.default]
}

resource "aws_s3_bucket_logging" "default" {
  # ... removed for brevity
  depends_on = [null_resource.default]
}

This seems to hack its way into the time delay being created by the retry logic in the associated PR by waiting 15 seconds after the bucket is created before creating the bucket logging object, and so far in testing this has fixed the aforementioned automated flows that were returning the error.

zack-is-cool · 2023-05-06T00:28:06Z

@nomeelnoj
interesting, I was trying to pass the s3 bucket object through a time_sleep for 90+ seconds and that didn't seem to work, still got the empty output error. I also didn't seem to get the error when creating the logging object when creating the s3 bucket (now deprecated.)

We're using terratest in our pipeline; a workaround we've implemented is RetryableTerraformErrors seems to work so far

	terraformOptions := &terraform.Options{
		TerraformDir: tempFolder,
		Upgrade:      false,
		VarFiles: []string{
			"fixtures.common.tfvars",
			"fixtures.insecure.tfvars",
		},
		RetryableTerraformErrors: map[string]string{
			".*empty output.*": "bug in aws_s3_bucket_logging, intermittent error",
		},
		MaxRetries:         5,
		TimeBetweenRetries: 5 * time.Second,
	}
	```

github-actions · 2023-06-30T01:51:51Z

This functionality has been released in v5.6.0 of the Terraform AWS Provider. Please see the Terraform documentation on provider versioning or reach out if you need any assistance upgrading.

For further feature requests or bug reports with this functionality, please create a new GitHub issue following the template. Thank you!

github-actions · 2023-07-30T02:08:42Z

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 have found a problem that seems similar to this, please open a new issue and complete the issue template so we can capture all the details necessary to investigate further.

zack-is-cool added bug Addresses a defect in current functionality. needs-triage Waiting for first response or review from a maintainer. labels May 3, 2023

github-actions bot added the service/s3 Issues and PRs that pertain to the s3 service. label May 3, 2023

justinretzolk removed the needs-triage Waiting for first response or review from a maintainer. label May 3, 2023

zack-is-cool mentioned this issue May 4, 2023

Intermittent error: "error reading S3 Bucket: empty output" defenseunicorns/delivery-aws-iac#207

Closed

This was referenced May 9, 2023

Race condition creating aws_s3_bucket_logging resource sometimes produces "logging: empty output" error navapbc/template-infra#258

Closed

Add workaround for empty logging race condition navapbc/template-infra#260

Closed

zack-is-cool mentioned this issue May 9, 2023

Track upstream aws_s3_bucket_logging bug report and remove workaround defenseunicorns/delivery-aws-iac#232

Closed

alewando mentioned this issue May 9, 2023

aws_s3_bucket_logging: Retry on empty logging configuration output #30916

Merged

jon-stewart mentioned this issue Jun 8, 2023

fix: avoid S3 bucket race condition lacework/terraform-aws-eks-audit-log#41

Merged

johnsonaj closed this as completed in #30916 Jun 26, 2023

github-actions bot added this to the v5.6.0 milestone Jun 26, 2023

github-actions bot locked as resolved and limited conversation to collaborators Jul 30, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[Bug]: Inconsistent "Logging: empty output error" with aws_s3_bucket_logging #31139

[Bug]: Inconsistent "Logging: empty output error" with aws_s3_bucket_logging #31139

zack-is-cool commented May 3, 2023 •

edited

Loading

github-actions bot commented May 3, 2023

zack-is-cool commented May 4, 2023

nomeelnoj commented May 5, 2023

zack-is-cool commented May 6, 2023

github-actions bot commented Jun 30, 2023

github-actions bot commented Jul 30, 2023

[Bug]: Inconsistent "Logging: empty output error" with aws_s3_bucket_logging #31139

[Bug]: Inconsistent "Logging: empty output error" with aws_s3_bucket_logging #31139

Comments

zack-is-cool commented May 3, 2023 • edited Loading

Terraform Core Version

AWS Provider Version

Affected Resource(s)

Expected Behavior

Actual Behavior

Relevant Error/Panic Output Snippet

Terraform Configuration Files

Steps to Reproduce

Debug Output

Panic Output

Important Factoids

References

Would you like to implement a fix?

github-actions bot commented May 3, 2023

Community Note

zack-is-cool commented May 4, 2023

nomeelnoj commented May 5, 2023

zack-is-cool commented May 6, 2023

github-actions bot commented Jun 30, 2023

github-actions bot commented Jul 30, 2023

zack-is-cool commented May 3, 2023 •

edited

Loading