Use slog logger and enable s3 http request logs

.github/workflows/s3-integration.yml

@@ -2,15 +2,13 @@ name: S3 Integration Tests
 
 on:
   workflow_dispatch:
-  # temporarily disabled until S3 implementation uses new structured logging format
-  # blocked by https://github.com/cloudfoundry/bosh-s3cli/pull/60 which needs to be integrated first 
-  # pull_request:
-  #   paths:
-  #   - ".github/workflows/s3-integration.yml"
-  #   - "s3/**"
-  # push:
-  #   branches:
-  #     - main
+  pull_request:
+    paths:
+    - ".github/workflows/s3-integration.yml"
+    - "s3/**"
+  push:
+    branches:
+      - main
 
 jobs:
   # AWS S3 US Integration Tests

README.md

@@ -21,9 +21,7 @@ Key points
   - additional endpoints needed by CAPI still missing
 - [Gcs](./gcs/README.md)
 - [S3](./s3/README.md)
-  - additional endpoints needed by CAPI still missing
-  - dev blocked by https://github.com/cloudfoundry/bosh-s3cli/pull/60
-  - integration tests disabled (they fail on logging format changes)
+  - additional endpoints needed by CAPI still missing 
 
 
 ## Build

main.go

@@ -23,7 +23,6 @@ func fatalLog(cmd string, err error) {
 	// If the object exists the exit status is 0, otherwise it is 3
 	// We are using `3` since `1` and `2` have special meanings
 	if _, ok := err.(*storage.NotExistsError); ok {
-		slog.Error("performing operation", "command", cmd, "error", err)
 		os.Exit(3)
 	}
 	slog.Error("performing operation", "command", cmd, "error", err)

s3/client/aws_s3_blobstore.go

@@ -4,7 +4,7 @@ import (
 	"errors"
 	"fmt"
 	"io"
-	"log"
+	"log/slog"
 	"strings"
 	"time"
 
@@ -84,18 +84,16 @@ func (b *awsS3Client) Put(src io.ReadSeeker, dest string) error {
 		if err != nil {
 			if _, ok := err.(manager.MultiUploadFailure); ok {
 				if retry == maxRetries {
-					log.Println("Upload retry limit exceeded:", err.Error())
 					return fmt.Errorf("upload retry limit exceeded: %s", err.Error())
 				}
 				retry++
 				time.Sleep(time.Second * time.Duration(retry))
 				continue
 			}
-			log.Println("Upload failed:", err.Error())
 			return fmt.Errorf("upload failure: %s", err.Error())
 		}
 
-		log.Println("Successfully uploaded file to", putResult.Location)
+		slog.Info("Successfully uploaded file", "location", putResult.Location)
 		return nil
 	}
 }
@@ -134,13 +132,13 @@ func (b *awsS3Client) Exists(dest string) (bool, error) {
 	_, err := b.s3Client.HeadObject(context.TODO(), existsParams)
 
 	if err == nil {
-		log.Printf("File '%s' exists in bucket '%s'\n", dest, b.s3cliConfig.BucketName)
+		slog.Info("Blob exists in bucket", "bucket", b.s3cliConfig.BucketName, "blob", dest)
 		return true, nil
 	}
 
 	var apiErr smithy.APIError
 	if errors.As(err, &apiErr) && apiErr.ErrorCode() == "NotFound" {
-		log.Printf("File '%s' does not exist in bucket '%s'\n", dest, b.s3cliConfig.BucketName)
+		slog.Info("Blob does not exist in bucket", "bucket", b.s3cliConfig.BucketName, "blob", dest)
 		return false, nil
 	}
 	return false, err

s3/client/client.go

@@ -2,7 +2,6 @@ package client
 
 import (
 	"errors"
-	"log"
 	"os"
 	"time"
 
@@ -43,7 +42,7 @@ func (c *S3CompatibleClient) Get(src string, dest string) error {
 func (c *S3CompatibleClient) Put(src string, dest string) error {
 	sourceFile, err := os.Open(src)
 	if err != nil {
-		log.Fatalln(err)
+		return err
 	}
 	defer sourceFile.Close() //nolint:errcheck
 	return c.awsS3BlobstoreClient.Put(sourceFile, dest)

s3/client/middlewares.go → s3/client/s3middleware/accept_encoding_fix.go

@@ -1,4 +1,4 @@
-package client
+package s3middleware
 
 import (
 	"context"

s3/client/s3middleware/http_logger.go

@@ -0,0 +1,56 @@
+package s3middleware
+
+import (
+	"log/slog"
+	"net/http"
+	"time"
+)
+
+type roundTripperFunc func(*http.Request) (*http.Response, error)
+
+func (f roundTripperFunc) RoundTrip(req *http.Request) (*http.Response, error) { return f(req) }
+
+func NewS3LoggingTransport(base http.RoundTripper) http.RoundTripper {
+	if base == nil {
+		base = http.DefaultTransport
+	}
+
+	return roundTripperFunc(func(req *http.Request) (*http.Response, error) {
+		start := time.Now()
+		resp, err := base.RoundTrip(req)
+		duration := time.Since(start)
+
+		attrs := []any{
+			"method", req.Method,
+			"url", req.URL.String(),
+			"host", req.Host,
+			"request_content_length", req.ContentLength,
+			"duration_ms", duration.Milliseconds(),
+		}
+
+		if resp != nil {
+			for k, v := range parseResponseFields(resp) {
+				attrs = append(attrs, k, v)
+			}
+		}
+
+		if err != nil {
+			attrs = append(attrs, "error", err.Error())
+			slog.Error("s3 http request failed", attrs...)
+			return resp, err
+		}
+
+		slog.Debug("s3 http request", attrs...)
+
+		return resp, nil
+	})
+}
+
+func parseResponseFields(resp *http.Response) map[string]any {
+	responseFields := make(map[string]any)
+	responseFields["status_code"] = resp.StatusCode
+	responseFields["response_content_length"] = resp.ContentLength
+	responseFields["request_id"] = resp.Header.Get("x-amz-request-id")
+	responseFields["extended_request_id"] = resp.Header.Get("x-amz-id-2")
+	return responseFields
+}

s3/client/s3middleware/http_logger_test.go

@@ -0,0 +1,65 @@
+package s3middleware
+
+import (
+	"bytes"
+	"errors"
+	"io"
+	"log/slog"
+	"net/http"
+	"net/http/httptest"
+	"strings"
+
+	. "github.com/onsi/ginkgo/v2"
+	. "github.com/onsi/gomega"
+)
+
+var _ = Describe("HttpLogger", func() {
+	var buf bytes.Buffer
+	BeforeEach(func() {
+		buf.Reset()
+		logger := slog.New(slog.NewJSONHandler(&buf, &slog.HandlerOptions{Level: slog.LevelDebug}))
+		slog.SetDefault(logger)
+	})
+
+	Context("when transport returns response,", func() {
+		It("log with 's3 http request' message", func() {
+			mockTransport := roundTripperFunc(func(req *http.Request) (*http.Response, error) {
+				return &http.Response{
+					StatusCode:    200,
+					Body:          io.NopCloser(strings.NewReader("OK")),
+					Header:        http.Header{"X-Amz-Request-Id": []string{"request-id"}, "X-Amz-Id-2": []string{"extended-request-id"}},
+					ContentLength: 3,
+				}, nil
+			})
+			loggingTransport := NewS3LoggingTransport(mockTransport)
+			req := httptest.NewRequest("GET", "http://example.com/test", nil)
+			_, _ = loggingTransport.RoundTrip(req) //nolint:errcheck
+			logs := buf.String()
+			Expect(logs).To(ContainSubstring(`"msg":"s3 http request"`))
+			Expect(logs).To(ContainSubstring(`"method":"GET"`))
+			Expect(logs).To(ContainSubstring(`"status_code":200`))
+			Expect(logs).To(ContainSubstring(`"request_id":"request-id"`))
+			Expect(logs).To(ContainSubstring(`"extended_request_id":"extended-request-id"`))
+			Expect(logs).To(ContainSubstring(`"response_content_length":3`))
+		})
+	})
+
+	Context("when transport returns error,", func() {
+		It("log with 's3 http request failed' message", func() {
+
+			hostNotFound := errors.New("dial tcp: lookup example.com: no such host")
+
+			mockTransport := roundTripperFunc(func(req *http.Request) (*http.Response, error) {
+				return nil, hostNotFound
+			})
+			loggingTransport := NewS3LoggingTransport(mockTransport)
+			req := httptest.NewRequest("GET", "http://example.com/test", nil)
+			_, _ = loggingTransport.RoundTrip(req) //nolint:errcheck
+			logs := buf.String()
+			Expect(logs).To(ContainSubstring(`"msg":"s3 http request failed"`))
+			Expect(logs).To(ContainSubstring(`"method":"GET"`))
+			Expect(logs).To(ContainSubstring(`"error"`))
+			Expect(logs).To(ContainSubstring("no such host"))
+		})
+	})
+})

s3/client/s3middleware/middleware_suite_test.go

@@ -0,0 +1,13 @@
+package s3middleware
+
+import (
+	"testing"
+
+	. "github.com/onsi/ginkgo/v2"
+	. "github.com/onsi/gomega"
+)
+
+func TestMiddleware(t *testing.T) {
+	RegisterFailHandler(Fail)
+	RunSpecs(t, "S3 Middleware")
+}

s3/client/sdk.go

@@ -13,6 +13,8 @@ import (
 	"github.com/aws/aws-sdk-go-v2/service/sts"
 	"github.com/aws/smithy-go/middleware"
 	boshhttp "github.com/cloudfoundry/bosh-utils/httpclient"
+	"github.com/cloudfoundry/storage-cli/common"
+	"github.com/cloudfoundry/storage-cli/s3/client/s3middleware"
 
 	s3cli_config "github.com/cloudfoundry/storage-cli/s3/config"
 )
@@ -23,7 +25,7 @@ func NewAwsS3Client(c *s3cli_config.S3Cli) (*s3.Client, error) {
 		// Setup middleware fixing request to Google - they expect the 'accept-encoding' header
 		// to not be included in the signature of the request. Not needed for "sign" commands
 		// since they only generate pre-signed URLs without making actual HTTP requests.
-		apiOptions = append(apiOptions, AddFixAcceptEncodingMiddleware)
+		apiOptions = append(apiOptions, s3middleware.AddFixAcceptEncodingMiddleware)
 	}
 	return NewAwsS3ClientWithApiOptions(c, apiOptions)
 }
@@ -40,6 +42,10 @@ func NewAwsS3ClientWithApiOptions(
 		httpClient = boshhttp.CreateDefaultClientInsecureSkipVerify()
 	}
 
+	if common.IsDebug() {
+		httpClient.Transport = s3middleware.NewS3LoggingTransport(httpClient.Transport)
+	}
+
 	options := []func(*config.LoadOptions) error{
 		config.WithHTTPClient(httpClient),
 	}

s3/integration/assertions.go

@@ -10,13 +10,11 @@ import (
 	"strings"
 	"time"
 
-	"github.com/cloudfoundry/storage-cli/s3/client"
-	"github.com/cloudfoundry/storage-cli/s3/config"
-	"github.com/onsi/gomega/gbytes"
-
 	"github.com/aws/aws-sdk-go-v2/aws"
 	"github.com/aws/aws-sdk-go-v2/service/s3"
 	"github.com/aws/aws-sdk-go-v2/service/s3/types"
+	"github.com/cloudfoundry/storage-cli/s3/client"
+	"github.com/cloudfoundry/storage-cli/s3/config"
 	. "github.com/onsi/gomega" //nolint:staticcheck
 )
 
@@ -99,7 +97,6 @@ func AssertLifecycleWorks(s3CLIPath string, cfg *config.S3Cli) {
 	s3CLISession, err = RunS3CLI(s3CLIPath, configPath, storageType, "exists", s3Filename)
 	Expect(err).ToNot(HaveOccurred())
 	Expect(s3CLISession.ExitCode()).To(Equal(3))
-	Expect(s3CLISession.Err).Should(gbytes.Say(`"error":"object does not exist"`))
 }
 
 func AssertOnPutFailures(cfg *config.S3Cli, content, errorMessage string) {

s3/integration/utils.go

@@ -10,6 +10,7 @@ import (
 	"github.com/aws/aws-sdk-go-v2/service/s3"
 	"github.com/aws/smithy-go/middleware"
 	"github.com/cloudfoundry/storage-cli/s3/client"
+	"github.com/cloudfoundry/storage-cli/s3/client/s3middleware"
 	"github.com/cloudfoundry/storage-cli/s3/config"
 
 	. "github.com/onsi/ginkgo/v2" //nolint:staticcheck
@@ -98,7 +99,7 @@ func CreateTracingS3Client(s3Config *config.S3Cli, calls *[]string) (*s3.Client,
 	var apiOptions []func(stack *middleware.Stack) error
 	// Setup middleware fixing request to Google - they expect the 'accept-encoding' header
 	// to not be included in the signature of the request.
-	apiOptions = append(apiOptions, client.AddFixAcceptEncodingMiddleware)
+	apiOptions = append(apiOptions, s3middleware.AddFixAcceptEncodingMiddleware)
 	// Use the centralized client creation logic with a custom middleware
 	apiOptions = append(apiOptions, func(stack *middleware.Stack) error {
 		return stack.Initialize.Add(createS3TracingMiddleware(calls), middleware.Before)