fix: fix debug log (notaryproject#1061)

Signed-off-by: Patrick Zheng <[email protected]>
Two-Hearts · Dec 10, 2024 · 1b84cba · 1b84cba
1 parent be4b875
commit 1b84cba
Show file tree

Hide file tree

Showing 4 changed files with 37 additions and 18 deletions.
diff --git a/internal/trace/context.go b/internal/trace/context.go
@@ -48,6 +48,7 @@ func WithLoggerLevel(ctx context.Context, level logrus.Level) context.Context {
 
 	// create logger
 	logger := logrus.New()
+	formatter.DisableQuote = true
 	logger.SetFormatter(&formatter)
 	logger.SetLevel(level)
 

diff --git a/internal/trace/transport.go b/internal/trace/transport.go
@@ -31,13 +31,27 @@ package trace
 
 import (
 	"context"
+	"fmt"
 	"net/http"
 	"strings"
+	"sync/atomic"
 
 	"github.com/notaryproject/notation-go/log"
 	"github.com/sirupsen/logrus"
 )
 
+var (
+	// requestCount records the number of logged request-response pairs and will
+	// be used as the unique id for the next pair.
+	requestCount uint64
+
+	// toScrub is a set of headers that should be scrubbed from the log.
+	toScrub = []string{
+		"Authorization",
+		"Set-Cookie",
+	}
+)
+
 // Transport is an http.RoundTripper that keeps track of the in-flight
 // request and add hooks to report HTTP tracing events.
 type Transport struct {
@@ -50,39 +64,43 @@ func NewTransport(base http.RoundTripper) *Transport {
 
 // RoundTrip calls base roundtrip while keeping track of the current request.
 func (t *Transport) RoundTrip(req *http.Request) (resp *http.Response, err error) {
+	id := atomic.AddUint64(&requestCount, 1) - 1
 	ctx := req.Context()
 	e := log.GetLogger(ctx)
 
-	e.Debugf("> Request: %q %q", req.Method, req.URL)
-	e.Debugf("> Request headers:")
-	logHeader(req.Header, e)
+	// log the request
+	e.Debugf("Request #%d\n> Request: %q %q\n> Request headers:\n%s",
+		id, req.Method, req.URL, logHeader(req.Header))
 
+	// log the response
 	resp, err = t.RoundTripper.RoundTrip(req)
 	if err != nil {
 		e.Errorf("Error in getting response: %w", err)
 	} else if resp == nil {
 		e.Errorf("No response obtained for request %s %q", req.Method, req.URL)
 	} else {
-		e.Debugf("< Response status: %q", resp.Status)
-		e.Debugf("< Response headers:")
-		logHeader(resp.Header, e)
+		e.Debugf("Response #%d\n< Response status: %q\n< Response headers:\n%s",
+			id, resp.Status, logHeader(resp.Header))
 	}
 	return resp, err
 }
 
 // logHeader prints out the provided header keys and values, with auth header
 // scrubbed.
-func logHeader(header http.Header, e log.Logger) {
+func logHeader(header http.Header) string {
 	if len(header) > 0 {
+		headers := []string{}
 		for k, v := range header {
-			if strings.EqualFold(k, "Authorization") {
-				v = []string{"*****"}
+			for _, h := range toScrub {
+				if strings.EqualFold(k, h) {
+					v = []string{"*****"}
+				}
 			}
-			e.Debugf("   %q: %q", k, strings.Join(v, ", "))
+			headers = append(headers, fmt.Sprintf("   %q: %q", k, strings.Join(v, ", ")))
 		}
-	} else {
-		e.Debugf("   Empty header")
+		return strings.Join(headers, "\n")
 	}
+	return "   Empty header"
 }
 
 // SetHTTPDebugLog sets up http debug log with logrus.Logger

diff --git a/test/e2e/suite/command/verify.go b/test/e2e/suite/command/verify.go
@@ -253,7 +253,7 @@ var _ = Describe("notation verify", func() {
 
 			notation.Exec("verify", artifact.ReferenceWithDigest(), "-v").
 				MatchKeyWords(VerifySuccessfully).
-				MatchErrKeyWords("Timestamp verification disabled: verifyTimestamp is set to \\\"afterCertExpiry\\\" and signing cert chain unexpired")
+				MatchErrKeyWords("Timestamp verification disabled: verifyTimestamp is set to \"afterCertExpiry\" and signing cert chain unexpired")
 		})
 	})
 })
diff --git a/test/e2e/suite/plugin/verify.go b/test/e2e/suite/plugin/verify.go
@@ -46,7 +46,7 @@ var _ = Describe("notation plugin verify", func() {
 				MatchErrKeyWords(
 					"Plugin verify-signature request",
 					"Plugin verify-signature response",
-					`{\"verificationResults\":{\"SIGNATURE_VERIFIER.REVOCATION_CHECK\":{\"success\":true},\"SIGNATURE_VERIFIER.TRUSTED_IDENTITY\":{\"success\":true}},\"processedAttributes\":null}`).
+					`{"verificationResults":{"SIGNATURE_VERIFIER.REVOCATION_CHECK":{"success":true},"SIGNATURE_VERIFIER.TRUSTED_IDENTITY":{"success":true}},"processedAttributes":null}`).
 				MatchKeyWords(VerifySuccessfully)
 		})
 	})
@@ -77,7 +77,7 @@ var _ = Describe("notation plugin verify", func() {
 				MatchErrKeyWords(
 					"Plugin verify-signature request",
 					"Plugin verify-signature response",
-					`revocation check by verification plugin \"e2e-plugin\" failed with reason \"revocation check failed\"`,
+					`revocation check by verification plugin "e2e-plugin" failed with reason "revocation check failed"`,
 					VerifyFailed)
 		})
 	})
@@ -108,7 +108,7 @@ var _ = Describe("notation plugin verify", func() {
 				MatchErrKeyWords(
 					"Plugin verify-signature request",
 					"Plugin verify-signature response",
-					`trusted identify verification by plugin \"e2e-plugin\" failed with reason \"trusted identity check failed\"`,
+					`trusted identify verification by plugin "e2e-plugin" failed with reason "trusted identity check failed"`,
 					VerifyFailed)
 		})
 	})
@@ -138,7 +138,7 @@ var _ = Describe("notation plugin verify", func() {
 				MatchErrKeyWords(
 					"Plugin verify-signature request",
 					"Plugin verify-signature response",
-					`{\"verificationResults\":{\"SIGNATURE_VERIFIER.REVOCATION_CHECK\":{\"success\":true},\"SIGNATURE_VERIFIER.TRUSTED_IDENTITY\":{\"success\":true}},\"processedAttributes\":null}`).
+					`{"verificationResults":{"SIGNATURE_VERIFIER.REVOCATION_CHECK":{"success":true},"SIGNATURE_VERIFIER.TRUSTED_IDENTITY":{"success":true}},"processedAttributes":null}`).
 				MatchKeyWords(VerifySuccessfully)
 		})
 	})
@@ -197,7 +197,7 @@ var _ = Describe("notation plugin verify", func() {
 				MatchErrKeyWords(
 					"Plugin verify-signature request",
 					"Plugin verify-signature response",
-					`{\"verificationResults\":{\"SIGNATURE_VERIFIER.REVOCATION_CHECK\":{\"success\":true},\"SIGNATURE_VERIFIER.TRUSTED_IDENTITY\":{\"success\":true}},\"processedAttributes\":null}`).
+					`{"verificationResults":{"SIGNATURE_VERIFIER.REVOCATION_CHECK":{"success":true},"SIGNATURE_VERIFIER.TRUSTED_IDENTITY":{"success":true}},"processedAttributes":null}`).
 				MatchKeyWords(VerifySuccessfully)
 		})
 	})