diff --git a/internal/backend/remote-state/s3/backend.go b/internal/backend/remote-state/s3/backend.go index 997045fd0c..2474f19df1 100644 --- a/internal/backend/remote-state/s3/backend.go +++ b/internal/backend/remote-state/s3/backend.go @@ -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") -}) diff --git a/internal/backend/remote-state/s3/backend_state.go b/internal/backend/remote-state/s3/backend_state.go index fb8e780422..81c523951b 100644 --- a/internal/backend/remote-state/s3/backend_state.go +++ b/internal/backend/remote-state/s3/backend_state.go @@ -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 diff --git a/internal/backend/remote-state/s3/backend_test.go b/internal/backend/remote-state/s3/backend_test.go index 4ab43bf61e..228ba3e407 100644 --- a/internal/backend/remote-state/s3/backend_test.go +++ b/internal/backend/remote-state/s3/backend_test.go @@ -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() diff --git a/internal/backend/remote-state/s3/client.go b/internal/backend/remote-state/s3/client.go index 8bdcab79ab..d49cfe387c 100644 --- a/internal/backend/remote-state/s3/client.go +++ b/internal/backend/remote-state/s3/client.go @@ -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 diff --git a/internal/backend/remote-state/s3/logging.go b/internal/backend/remote-state/s3/logging.go new file mode 100644 index 0000000000..956ecc650a --- /dev/null +++ b/internal/backend/remote-state/s3/logging.go @@ -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, + ) +}