aherman
/
terraform
mirror of https://github.com/hashicorp/terraform
1
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

Merge pull request #33850 from hashicorp/s3/request-logging

Browse Source 
backend/s3: Restore HTTP request/response logging
s3/f-check-for-bucket-in-init
Graham Davison 3 years ago committed by GitHub
parent a560730376 85f68bcbde
commit 21326422fb
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
5 changed files with 214 additions and 57 deletions
Show Stats Download Patch File Download Diff File

18
internal/backend/remote-state/s3/backend.go
Unescape View File

@ -11,7 +11,6 @@ import (
"regexp"
"sort"
"strings"
"sync"
"time"
"github.com/aws/aws-sdk-go-v2/aws"
@ -20,10 +19,8 @@ import (
"github.com/aws/aws-sdk-go-v2/service/s3"
awsbase "github.com/hashicorp/aws-sdk-go-base/v2"
baselogging "github.com/hashicorp/aws-sdk-go-base/v2/logging"
"github.com/hashicorp/go-hclog"
"github.com/hashicorp/terraform/internal/backend"
"github.com/hashicorp/terraform/internal/configs/configschema"
"github.com/hashicorp/terraform/internal/logging"
"github.com/hashicorp/terraform/internal/tfdiags"
"github.com/hashicorp/terraform/version"
"github.com/zclconf/go-cty/cty"
@ -607,6 +604,8 @@ func formatDeprecations(attrs map[string]string) string {
// via PrepareConfig.
func (b *Backend) Configure(obj cty.Value) tfdiags.Diagnostics {
ctx := context.TODO()
log := logger()
log = logWithOperation(log, operationBackendConfigure)
var diags tfdiags.Diagnostics
if obj.IsNull() {
@ -632,6 +631,12 @@ func (b *Backend) Configure(obj cty.Value) tfdiags.Diagnostics {
b.bucketName = stringAttr(obj, "bucket")
b.keyName = stringAttr(obj, "key")
log = log.With(
logKeyBucket, b.bucketName,
logKeyPath, b.keyName,
)
b.acl = stringAttr(obj, "acl")
b.workspaceKeyPrefix = stringAttrDefault(obj, "workspace_key_prefix", "env:")
b.serverSideEncryption = boolAttr(obj, "encrypt")
@ -698,8 +703,6 @@ func (b *Backend) Configure(obj cty.Value) tfdiags.Diagnostics {
}
}
log := logger()
ctx, baselog := baselogging.NewHcLogger(ctx, log)
cfg := &awsbase.Config{
@ -1643,8 +1646,3 @@ func deprecatedEnvVarDiag(envvar, replacement string) tfdiags.Diagnostic {
fmt.Sprintf(`The environment variable "%s" is deprecated. Use environment variable "%s" instead.`, envvar, replacement),
)
}
var logger = sync.OnceValue(func() hclog.Logger {
l := logging.HCLogger()
return l.Named("backend-s3")
})

21
internal/backend/remote-state/s3/backend_state.go
Unescape View File

@ -15,6 +15,7 @@ import (
"github.com/aws/aws-sdk-go-v2/service/s3"
s3types "github.com/aws/aws-sdk-go-v2/service/s3/types"
baselogging "github.com/hashicorp/aws-sdk-go-base/v2/logging"
"github.com/hashicorp/terraform/internal/backend"
"github.com/hashicorp/terraform/internal/states"
"github.com/hashicorp/terraform/internal/states/remote"
@ -25,6 +26,11 @@ func (b *Backend) Workspaces() ([]string, error) {
const maxKeys = 1000
ctx := context.TODO()
log := logger()
log = logWithOperation(log, operationBackendWorkspaces)
log = log.With(
logKeyBucket, b.bucketName,
)
prefix := ""
@ -32,6 +38,10 @@ func (b *Backend) Workspaces() ([]string, error) {
prefix = b.workspaceKeyPrefix + "/"
}
log = log.With(
logKeyBackendWorkspacePrefix, prefix,
)
params := &s3.ListObjectsV2Input{
Bucket: aws.String(b.bucketName),
Prefix: aws.String(prefix),
@ -40,6 +50,9 @@ func (b *Backend) Workspaces() ([]string, error) {
wss := []string{backend.DefaultStateName}
ctx, baselog := baselogging.NewHcLogger(ctx, log)
ctx = baselogging.RegisterLogger(ctx, baselog)
pages := s3.NewListObjectsV2Paginator(b.s3Client, params)
for pages.HasMorePages() {
page, err := pages.NextPage(ctx)
@ -102,10 +115,18 @@ func (b *Backend) keyEnv(key string) string {
}
func (b *Backend) DeleteWorkspace(name string, _ bool) error {
log := logger()
log = logWithOperation(log, operationBackendDeleteWorkspace)
log = log.With(
logKeyBackendWorkspace, name,
)
if name == backend.DefaultStateName || name == "" {
return fmt.Errorf("can't delete default state")
}
log.Info("Deleting workspace")
client, err := b.remoteClient(name)
if err != nil {
return err

2
internal/backend/remote-state/s3/backend_test.go
Unescape View File

@ -1328,7 +1328,7 @@ func TestBackendConfig_PrepareConfigWithEnvVars(t *testing.T) {
}
}
func TestBackend(t *testing.T) {
func TestBackendBasic(t *testing.T) {
testACC(t)
ctx := context.TODO()

141
internal/backend/remote-state/s3/client.go
Unescape View File

@ -21,6 +21,8 @@ import (
dynamodbtypes "github.com/aws/aws-sdk-go-v2/service/dynamodb/types"
"github.com/aws/aws-sdk-go-v2/service/s3"
s3types "github.com/aws/aws-sdk-go-v2/service/s3/types"
baselogging "github.com/hashicorp/aws-sdk-go-base/v2/logging"
"github.com/hashicorp/go-hclog"
multierror "github.com/hashicorp/go-multierror"
uuid "github.com/hashicorp/go-uuid"
"github.com/hashicorp/terraform/internal/states/remote"
@ -61,6 +63,12 @@ var testChecksumHook func()
func (c *RemoteClient) Get() (payload *remote.Payload, err error) {
ctx := context.TODO()
log := c.logger(operationClientGet)
ctx, baselog := baselogging.NewHcLogger(ctx, log)
ctx = baselogging.RegisterLogger(ctx, baselog)
log.Info("Downloading remote state")
deadline := time.Now().Add(consistencyRetryTimeout)
@ -82,9 +90,14 @@ func (c *RemoteClient) Get() (payload *remote.Payload, err error) {
// verify that this state is what we expect
if expected, err := c.getMD5(ctx); err != nil {
log.Printf("[WARN] failed to fetch state md5: %s", err)
log.Warn("failed to fetch state MD5",
"error", err,
)
} else if len(expected) > 0 && !bytes.Equal(expected, digest) {
log.Printf("[WARN] state md5 mismatch: expected '%x', got '%x'", expected, digest)
log.Warn("state MD5 mismatch",
"expected", expected,
"actual", digest,
)
if testChecksumHook != nil {
testChecksumHook()
@ -92,7 +105,7 @@ func (c *RemoteClient) Get() (payload *remote.Payload, err error) {
if time.Now().Before(deadline) {
time.Sleep(consistencyRetryPollInterval)
log.Println("[INFO] retrying S3 RemoteClient.Get...")
log.Info("retrying S3 RemoteClient.Get")
continue
}
@ -170,6 +183,10 @@ func (c *RemoteClient) get(ctx context.Context) (*remote.Payload, error) {
func (c *RemoteClient) Put(data []byte) error {
ctx := context.TODO()
log := c.logger(operationClientPut)
ctx, baselog := baselogging.NewHcLogger(ctx, log)
ctx = baselogging.RegisterLogger(ctx, baselog)
contentType := "application/json"
@ -197,7 +214,7 @@ func (c *RemoteClient) Put(data []byte) error {
input.ACL = s3types.ObjectCannedACL(c.acl)
}
log.Printf("[DEBUG] Uploading remote state to S3: %#v", input)
log.Info("Uploading remote state")
uploader := manager.NewUploader(c.s3Client)
_, err := uploader.Upload(ctx, input)
@ -217,6 +234,12 @@ func (c *RemoteClient) Put(data []byte) error {
func (c *RemoteClient) Delete() error {
ctx := context.TODO()
log := c.logger(operationClientDelete)
ctx, baselog := baselogging.NewHcLogger(ctx, log)
ctx = baselogging.RegisterLogger(ctx, baselog)
log.Info("Deleting remote state")
_, err := c.s3Client.DeleteObject(ctx, &s3.DeleteObjectInput{
Bucket: aws.String(c.bucketName),
@ -228,7 +251,9 @@ func (c *RemoteClient) Delete() error {
}
if err := c.deleteMD5(ctx); err != nil {
log.Printf("error deleting state md5: %s", err)
log.Error("deleting state MD5",
"error", err,
)
}
return nil
@ -236,6 +261,7 @@ func (c *RemoteClient) Delete() error {
func (c *RemoteClient) Lock(info *statemgr.LockInfo) (string, error) {
ctx := context.TODO()
log := c.logger(operationLockerLock)
if c.ddbTable == "" {
return "", nil
@ -252,6 +278,12 @@ func (c *RemoteClient) Lock(info *statemgr.LockInfo) (string, error) {
info.ID = lockID
}
log = logWithLockInfo(log, info)
ctx, baselog := baselogging.NewHcLogger(ctx, log)
ctx = baselogging.RegisterLogger(ctx, baselog)
log.Info("Locking remote state")
putParams := &dynamodb.PutItemInput{
Item: map[string]dynamodbtypes.AttributeValue{
"LockID": &dynamodbtypes.AttributeValueMemberS{
@ -282,6 +314,55 @@ func (c *RemoteClient) Lock(info *statemgr.LockInfo) (string, error) {
return info.ID, nil
}
func (c *RemoteClient) Unlock(id string) error {
ctx := context.TODO()
log := c.logger(operationLockerUnlock)
log = logWithLockID(log, id)
ctx, baselog := baselogging.NewHcLogger(ctx, log)
ctx = baselogging.RegisterLogger(ctx, baselog)
if c.ddbTable == "" {
return nil
}
lockErr := &statemgr.LockError{}
log.Info("Unlocking remote state")
// TODO: store the path and lock ID in separate fields, and have proper
// projection expression only delete the lock if both match, rather than
// checking the ID from the info field first.
lockInfo, err := c.getLockInfo(ctx)
if err != nil {
lockErr.Err = fmt.Errorf("failed to retrieve lock info for lock ID %q: %s", id, err)
return lockErr
}
lockErr.Info = lockInfo
if lockInfo.ID != id {
lockErr.Err = fmt.Errorf("lock ID %q does not match existing lock (%q)", id, lockInfo.ID)
return lockErr
}
params := &dynamodb.DeleteItemInput{
Key: map[string]dynamodbtypes.AttributeValue{
"LockID": &dynamodbtypes.AttributeValueMemberS{
Value: c.lockPath(),
},
},
TableName: aws.String(c.ddbTable),
}
_, err = c.dynClient.DeleteItem(ctx, params)
if err != nil {
lockErr.Err = err
return lockErr
}
return nil
}
func (c *RemoteClient) getMD5(ctx context.Context) ([]byte, error) {
if c.ddbTable == "" {
return nil, nil
@ -400,47 +481,6 @@ func (c *RemoteClient) getLockInfo(ctx context.Context) (*statemgr.LockInfo, err
return lockInfo, nil
}
func (c *RemoteClient) Unlock(id string) error {
ctx := context.TODO()
if c.ddbTable == "" {
return nil
}
lockErr := &statemgr.LockError{}
// TODO: store the path and lock ID in separate fields, and have proper
// projection expression only delete the lock if both match, rather than
// checking the ID from the info field first.
lockInfo, err := c.getLockInfo(ctx)
if err != nil {
lockErr.Err = fmt.Errorf("failed to retrieve lock info: %s", err)
return lockErr
}
lockErr.Info = lockInfo
if lockInfo.ID != id {
lockErr.Err = fmt.Errorf("lock id %q does not match existing lock", id)
return lockErr
}
params := &dynamodb.DeleteItemInput{
Key: map[string]dynamodbtypes.AttributeValue{
"LockID": &dynamodbtypes.AttributeValueMemberS{
Value: c.lockPath(),
},
},
TableName: aws.String(c.ddbTable),
}
_, err = c.dynClient.DeleteItem(ctx, params)
if err != nil {
lockErr.Err = err
return lockErr
}
return nil
}
func (c *RemoteClient) lockPath() string {
return fmt.Sprintf("%s/%s", c.bucketName, c.path)
}
@ -450,6 +490,15 @@ func (c *RemoteClient) getSSECustomerKeyMD5() string {
return base64.StdEncoding.EncodeToString(b[:])
}
// logger returns the S3 backend logger configured with the client's bucket and path and the operation
func (c *RemoteClient) logger(operation string) hclog.Logger {
log := logger().With(
logKeyBucket, c.bucketName,
logKeyPath, c.path,
)
return logWithOperation(log, operation)
}
const errBadChecksumFmt = `state data in S3 does not have the expected content.
This may be caused by unusually long delays in S3 processing a previous state

89
internal/backend/remote-state/s3/logging.go
Unescape View File

@ -0,0 +1,89 @@
// Copyright (c) HashiCorp, Inc.
// SPDX-License-Identifier: BUSL-1.1
package s3
import (
"sync"
"github.com/hashicorp/go-hclog"
"github.com/hashicorp/go-uuid"
"github.com/hashicorp/terraform/internal/logging"
"github.com/hashicorp/terraform/internal/states/statemgr"
)
const (
logKeyBucket = "tf_backend.s3.bucket"
logKeyPath = "tf_backend.s3.path"
)
const (
logKeyBackendLockId = "tf_backend.lock.id"
logKeyBackendLockOperation = "tf_backend.lock.operation"
logKeyBackendLockInfo = "tf_backend.lock.info"
logKeyBackendLockWho = "tf_backend.lock.who"
logKeyBackendLockVersion = "tf_backend.lock.version"
logKeyBackendLockPath = "tf_backend.lock.path"
)
const (
logKeyBackendOperation = "tf_backend.operation"
logKeyBackendRequestId = "tf_backend.req_id" // Using "req_id" to match pattern for provider logging
logKeyBackendWorkspace = "tf_backend.workspace"
logKeyBackendWorkspacePrefix = "tf_backend.workspace-prefix"
)
const (
// operationBackendConfigSchema = "ConfigSchema"
// operationBackendPrepareConfig = "PrepareConfig"
operationBackendConfigure = "Configure"
// operationBackendStateMgr = "StateMgr"
operationBackendDeleteWorkspace = "DeleteWorkspace"
operationBackendWorkspaces = "Workspaces"
)
const (
operationClientGet = "Get"
operationClientPut = "Put"
operationClientDelete = "Delete"
)
const (
operationLockerLock = "Lock"
operationLockerUnlock = "Unlock"
)
var logger = sync.OnceValue(func() hclog.Logger {
l := logging.HCLogger()
return l.Named("backend-s3")
})
func logWithOperation(in hclog.Logger, operation string) hclog.Logger {
log := in.With(
logKeyBackendOperation, operation,
)
if id, err := uuid.GenerateUUID(); err == nil {
log = log.With(
logKeyBackendRequestId, id,
)
}
return log
}
func logWithLockInfo(in hclog.Logger, info *statemgr.LockInfo) hclog.Logger {
return in.With(
logKeyBackendLockId, info.ID,
logKeyBackendLockOperation, info.Operation,
logKeyBackendLockInfo, info.Info,
logKeyBackendLockWho, info.Who,
logKeyBackendLockVersion, info.Version,
logKeyBackendLockPath, info.Path,
)
}
func logWithLockID(in hclog.Logger, id string) hclog.Logger {
return in.With(
logKeyBackendLockId, id,
)
}
Write Preview
Loading…
Cancel
Save