From cb8b0299063c3679b5dbc8e15ebd99e3d22cdafe Mon Sep 17 00:00:00 2001 From: Sylvia Lei Date: Mon, 23 Sep 2024 18:36:43 +0800 Subject: [PATCH 01/28] add text_formatter.go Signed-off-by: Lixia (Sylvia) Lei --- internal/trace/context.go | 9 ++++++- internal/trace/text_formatter.go | 45 ++++++++++++++++++++++++++++++++ internal/trace/transport.go | 4 +-- 3 files changed, 55 insertions(+), 3 deletions(-) create mode 100644 internal/trace/text_formatter.go diff --git a/internal/trace/context.go b/internal/trace/context.go index d55c3812d..82329bc4a 100644 --- a/internal/trace/context.go +++ b/internal/trace/context.go @@ -36,7 +36,14 @@ func NewLogger(ctx context.Context, debug bool) (context.Context, logrus.FieldLo } logger := logrus.New() - logger.SetFormatter(&logrus.TextFormatter{DisableQuote: true}) + // logger.SetFormatter(&logrus.TextFormatter{ + // DisableQuote: true, + // FullTimestamp: true, + // DisableLevelTruncation: true, + // ForceColors: true, + // }) + logger.SetFormatter(&TextFormatter{}) + logger.SetLevel(logLevel) entry := logger.WithContext(ctx) return context.WithValue(ctx, loggerKey, entry), entry diff --git a/internal/trace/text_formatter.go b/internal/trace/text_formatter.go new file mode 100644 index 000000000..897fe18c4 --- /dev/null +++ b/internal/trace/text_formatter.go @@ -0,0 +1,45 @@ +/* +Copyright The ORAS Authors. +Licensed under the Apache License, Version 2.0 (the "License"); +you may not use this file except in compliance with the License. +You may obtain a copy of the License at + +http://www.apache.org/licenses/LICENSE-2.0 + +Unless required by applicable law or agreed to in writing, software +distributed under the License is distributed on an "AS IS" BASIS, +WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +See the License for the specific language governing permissions and +limitations under the License. +*/ + +package trace + +import ( + "bytes" + "fmt" + "strings" + "time" + + "github.com/sirupsen/logrus" +) + +// TextFormatter formats logs into text. +type TextFormatter struct{} + +// logEntrySeperator is the separator between log entries. +const logEntrySeperator = "\n\n\n" // two empty lines + +// Format renders a single log entry. +func (f *TextFormatter) Format(entry *logrus.Entry) ([]byte, error) { + var buf bytes.Buffer + + timestamp := entry.Time.Format(time.RFC3339Nano) + levelText := strings.ToUpper(entry.Level.String()) + buf.WriteString(fmt.Sprintf("[%s] %s: %s", timestamp, levelText, entry.Message)) + buf.WriteString(logEntrySeperator) + + // TODO: with fields? + + return buf.Bytes(), nil +} diff --git a/internal/trace/transport.go b/internal/trace/transport.go index 76630eb23..f8564d56e 100644 --- a/internal/trace/transport.go +++ b/internal/trace/transport.go @@ -54,7 +54,7 @@ func (t *Transport) RoundTrip(req *http.Request) (resp *http.Response, err error e := Logger(ctx) // log the request - e.Debugf("Request #%d\n> Request URL: %q\n> Request method: %q\n> Request headers:\n%s", + e.Debugf("--> Request #%d\n> Request URL: %q\n> Request method: %q\n> Request headers:\n%s", id, req.URL, req.Method, logHeader(req.Header)) // log the response @@ -64,7 +64,7 @@ func (t *Transport) RoundTrip(req *http.Request) (resp *http.Response, err error } else if resp == nil { e.Errorf("No response obtained for request %s %q", req.Method, req.URL) } else { - e.Debugf("Response #%d\n< Response Status: %q\n< Response headers:\n%s", + e.Debugf("<-- Response #%d\n< Response Status: %q\n< Response headers:\n%s", id, resp.Status, logHeader(resp.Header)) } return resp, err From f4ca1f429573618a0cbdb0ee16e9c8c70dc96b5c Mon Sep 17 00:00:00 2001 From: "Lixia (Sylvia) Lei" Date: Thu, 21 Nov 2024 23:37:05 +0800 Subject: [PATCH 02/28] logging fields Signed-off-by: Lixia (Sylvia) Lei --- cmd/oras/root/repo/ls.go | 7 +++++++ internal/trace/text_formatter.go | 14 ++++++++++---- internal/trace/transport.go | 4 ++++ 3 files changed, 21 insertions(+), 4 deletions(-) diff --git a/cmd/oras/root/repo/ls.go b/cmd/oras/root/repo/ls.go index 501ee050b..85fc92d9a 100644 --- a/cmd/oras/root/repo/ls.go +++ b/cmd/oras/root/repo/ls.go @@ -77,6 +77,13 @@ func listRepository(cmd *cobra.Command, opts *repositoryOptions) error { if err != nil { return err } + + // TEST: to be removed + logger = logger.WithField("registry", reg.Reference.Host()) + logger = logger.WithField("testkey", 123) + logger.Info("test info") + logger.Warn("test warn") + err = reg.Repositories(ctx, opts.last, func(repos []string) error { for _, repo := range repos { if subRepo, found := strings.CutPrefix(repo, opts.namespace); found { diff --git a/internal/trace/text_formatter.go b/internal/trace/text_formatter.go index 897fe18c4..a8c937a4f 100644 --- a/internal/trace/text_formatter.go +++ b/internal/trace/text_formatter.go @@ -28,7 +28,7 @@ import ( type TextFormatter struct{} // logEntrySeperator is the separator between log entries. -const logEntrySeperator = "\n\n\n" // two empty lines +const logEntrySeperator = "\n\n" // two empty lines // Format renders a single log entry. func (f *TextFormatter) Format(entry *logrus.Entry) ([]byte, error) { @@ -36,10 +36,16 @@ func (f *TextFormatter) Format(entry *logrus.Entry) ([]byte, error) { timestamp := entry.Time.Format(time.RFC3339Nano) levelText := strings.ToUpper(entry.Level.String()) - buf.WriteString(fmt.Sprintf("[%s] %s: %s", timestamp, levelText, entry.Message)) - buf.WriteString(logEntrySeperator) + buf.WriteString(fmt.Sprintf("[%s] %s: %s\n", timestamp, levelText, entry.Message)) + // printing fields + buf.WriteString("[Data]:\n") + for k, v := range entry.Data { + buf.WriteString(fmt.Sprintf(" %s=%v\n", k, v)) + } + + // TODO: body? - // TODO: with fields? + buf.WriteString(logEntrySeperator) return buf.Bytes(), nil } diff --git a/internal/trace/transport.go b/internal/trace/transport.go index f8564d56e..d3467550a 100644 --- a/internal/trace/transport.go +++ b/internal/trace/transport.go @@ -53,6 +53,10 @@ func (t *Transport) RoundTrip(req *http.Request) (resp *http.Response, err error ctx := req.Context() e := Logger(ctx) + // TEST: to be removed + e = e.WithField("host", req.Host) + e = e.WithField("testkey", 123) + // log the request e.Debugf("--> Request #%d\n> Request URL: %q\n> Request method: %q\n> Request headers:\n%s", id, req.URL, req.Method, logHeader(req.Header)) From adda59d4e2e4c9b7dd95dbd66686f20c030ece2e Mon Sep 17 00:00:00 2001 From: "Lixia (Sylvia) Lei" Date: Fri, 29 Nov 2024 15:53:24 +0800 Subject: [PATCH 03/28] refine format Signed-off-by: Lixia (Sylvia) Lei --- internal/trace/text_formatter.go | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/internal/trace/text_formatter.go b/internal/trace/text_formatter.go index a8c937a4f..359fbfe6c 100644 --- a/internal/trace/text_formatter.go +++ b/internal/trace/text_formatter.go @@ -36,11 +36,11 @@ func (f *TextFormatter) Format(entry *logrus.Entry) ([]byte, error) { timestamp := entry.Time.Format(time.RFC3339Nano) levelText := strings.ToUpper(entry.Level.String()) - buf.WriteString(fmt.Sprintf("[%s] %s: %s\n", timestamp, levelText, entry.Message)) - // printing fields - buf.WriteString("[Data]:\n") + buf.WriteString(fmt.Sprintf("[%s][%s]: %s\n", timestamp, levelText, entry.Message)) + // printing data fields + buf.WriteString("==Data==\n") for k, v := range entry.Data { - buf.WriteString(fmt.Sprintf(" %s=%v\n", k, v)) + buf.WriteString(fmt.Sprintf(" {%s=%v}\n", k, v)) } // TODO: body? From 9d9fc127ba9505e89f3a6654d673fb2e7b8a8010 Mon Sep 17 00:00:00 2001 From: "Lixia (Sylvia) Lei" Date: Fri, 29 Nov 2024 17:18:52 +0800 Subject: [PATCH 04/28] draft print body Signed-off-by: Lixia (Sylvia) Lei --- internal/trace/text_formatter.go | 4 +--- internal/trace/transport.go | 33 ++++++++++++++++++++++++++++++-- 2 files changed, 32 insertions(+), 5 deletions(-) diff --git a/internal/trace/text_formatter.go b/internal/trace/text_formatter.go index 359fbfe6c..e7b33d6c9 100644 --- a/internal/trace/text_formatter.go +++ b/internal/trace/text_formatter.go @@ -40,11 +40,9 @@ func (f *TextFormatter) Format(entry *logrus.Entry) ([]byte, error) { // printing data fields buf.WriteString("==Data==\n") for k, v := range entry.Data { - buf.WriteString(fmt.Sprintf(" {%s=%v}\n", k, v)) + buf.WriteString(fmt.Sprintf(" %s=%v\n", k, v)) } - // TODO: body? - buf.WriteString(logEntrySeperator) return buf.Bytes(), nil diff --git a/internal/trace/transport.go b/internal/trace/transport.go index d3467550a..7b170efcc 100644 --- a/internal/trace/transport.go +++ b/internal/trace/transport.go @@ -16,7 +16,9 @@ limitations under the License. package trace import ( + "bytes" "fmt" + "io" "net/http" "strings" "sync/atomic" @@ -34,6 +36,9 @@ var ( } ) +// TODO: is this number reasonable? add docs +const bodySizeLimit int64 = 8 * 1024 // 8 KiB + // Transport is an http.RoundTripper that keeps track of the in-flight // request and add hooks to report HTTP tracing events. type Transport struct { @@ -68,8 +73,8 @@ func (t *Transport) RoundTrip(req *http.Request) (resp *http.Response, err error } else if resp == nil { e.Errorf("No response obtained for request %s %q", req.Method, req.URL) } else { - e.Debugf("<-- Response #%d\n< Response Status: %q\n< Response headers:\n%s", - id, resp.Status, logHeader(resp.Header)) + e.Debugf("<-- Response #%d\n< Response Status: %q\n< Response headers:\n%s\n< Response body:\n%s", + id, resp.Status, logHeader(resp.Header), logResponseBody(resp)) } return resp, err } @@ -91,3 +96,27 @@ func logHeader(header http.Header) string { } return " Empty header" } + +// TODO: test and docs +func logResponseBody(resp *http.Response) string { + if resp.Body == nil { + return " Empty body" + } + contentType := resp.Header.Get("Content-Type") + if !strings.HasPrefix(contentType, "application/json") && !strings.HasPrefix(contentType, "text/") { + return " Body is hidden due to unsupported content type" + } + + // TODO: if content type is json, pretty print the json? + var builder strings.Builder + lr := io.LimitReader(resp.Body, bodySizeLimit) + bodyBytes, err := io.ReadAll(lr) + if err != nil { + return fmt.Sprintf(" Error reading response body: %v", err) + } + builder.Write(bodyBytes) + resp.Body = io.NopCloser(bytes.NewBuffer(bodyBytes)) + + // TODO: add ... if body is larger than bodySizeLimit + return builder.String() +} From 1cc9750bd75283096cf3256f68ae358f0a5b79b2 Mon Sep 17 00:00:00 2001 From: "Lixia (Sylvia) Lei" Date: Sat, 30 Nov 2024 18:13:19 +0800 Subject: [PATCH 05/28] refine Signed-off-by: Lixia (Sylvia) Lei --- internal/trace/text_formatter.go | 8 +++++--- internal/trace/transport.go | 26 +++++++++++++++++--------- 2 files changed, 22 insertions(+), 12 deletions(-) diff --git a/internal/trace/text_formatter.go b/internal/trace/text_formatter.go index e7b33d6c9..70bba58ae 100644 --- a/internal/trace/text_formatter.go +++ b/internal/trace/text_formatter.go @@ -38,9 +38,11 @@ func (f *TextFormatter) Format(entry *logrus.Entry) ([]byte, error) { levelText := strings.ToUpper(entry.Level.String()) buf.WriteString(fmt.Sprintf("[%s][%s]: %s\n", timestamp, levelText, entry.Message)) // printing data fields - buf.WriteString("==Data==\n") - for k, v := range entry.Data { - buf.WriteString(fmt.Sprintf(" %s=%v\n", k, v)) + if len(entry.Data) != 0 { + buf.WriteString("[Data]:\n") + for k, v := range entry.Data { + buf.WriteString(fmt.Sprintf(" %s=%v\n", k, v)) + } } buf.WriteString(logEntrySeperator) diff --git a/internal/trace/transport.go b/internal/trace/transport.go index 7b170efcc..23450d9fe 100644 --- a/internal/trace/transport.go +++ b/internal/trace/transport.go @@ -36,8 +36,7 @@ var ( } ) -// TODO: is this number reasonable? add docs -const bodySizeLimit int64 = 8 * 1024 // 8 KiB +const payloadSizeLimit int64 = 4 * 1024 * 1024 // 4 MiB // Transport is an http.RoundTripper that keeps track of the in-flight // request and add hooks to report HTTP tracing events. @@ -94,22 +93,21 @@ func logHeader(header http.Header) string { } return strings.Join(headers, "\n") } - return " Empty header" + return " " } // TODO: test and docs func logResponseBody(resp *http.Response) string { - if resp.Body == nil { - return " Empty body" + if resp.Body == nil || resp.ContentLength <= 0 { + return " " } contentType := resp.Header.Get("Content-Type") - if !strings.HasPrefix(contentType, "application/json") && !strings.HasPrefix(contentType, "text/") { - return " Body is hidden due to unsupported content type" + if !shouldPrint(contentType) { + return " Body of this content type is not printed" } - // TODO: if content type is json, pretty print the json? var builder strings.Builder - lr := io.LimitReader(resp.Body, bodySizeLimit) + lr := io.LimitReader(resp.Body, payloadSizeLimit) bodyBytes, err := io.ReadAll(lr) if err != nil { return fmt.Sprintf(" Error reading response body: %v", err) @@ -120,3 +118,13 @@ func logResponseBody(resp *http.Response) string { // TODO: add ... if body is larger than bodySizeLimit return builder.String() } + +func shouldPrint(contentType string) bool { + if strings.HasPrefix(contentType, "application/json") || strings.HasSuffix(contentType, "+json") { + return true + } + if strings.HasPrefix(contentType, "text/") { + return true + } + return false +} From 5529fcffd2c2102c91e9d98e331e314e280e9726 Mon Sep 17 00:00:00 2001 From: "Lixia (Sylvia) Lei" Date: Sat, 30 Nov 2024 18:44:36 +0800 Subject: [PATCH 06/28] tee Signed-off-by: Lixia (Sylvia) Lei --- internal/trace/transport.go | 13 ++++++++----- 1 file changed, 8 insertions(+), 5 deletions(-) diff --git a/internal/trace/transport.go b/internal/trace/transport.go index 23450d9fe..e5ef0c7eb 100644 --- a/internal/trace/transport.go +++ b/internal/trace/transport.go @@ -37,6 +37,7 @@ var ( ) const payloadSizeLimit int64 = 4 * 1024 * 1024 // 4 MiB +// const payloadSizeLimit int64 = 8 // TEST // Transport is an http.RoundTripper that keeps track of the in-flight // request and add hooks to report HTTP tracing events. @@ -105,17 +106,19 @@ func logResponseBody(resp *http.Response) string { if !shouldPrint(contentType) { return " Body of this content type is not printed" } + if resp.ContentLength > payloadSizeLimit { + return fmt.Sprintf(" Body larger to %d bytes is not printed", payloadSizeLimit) + } var builder strings.Builder - lr := io.LimitReader(resp.Body, payloadSizeLimit) - bodyBytes, err := io.ReadAll(lr) + // TODO: what if body has been read out? + tr := io.TeeReader(resp.Body, &builder) + bodyBytes, err := io.ReadAll(tr) if err != nil { return fmt.Sprintf(" Error reading response body: %v", err) } - builder.Write(bodyBytes) - resp.Body = io.NopCloser(bytes.NewBuffer(bodyBytes)) + resp.Body = io.NopCloser(bytes.NewReader(bodyBytes)) - // TODO: add ... if body is larger than bodySizeLimit return builder.String() } From 520bd1f6139e67d6b17025dcf05409ed2ab70e27 Mon Sep 17 00:00:00 2001 From: "Lixia (Sylvia) Lei" Date: Sat, 30 Nov 2024 23:31:56 +0800 Subject: [PATCH 07/28] revert text Signed-off-by: Lixia (Sylvia) Lei --- internal/trace/transport.go | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/internal/trace/transport.go b/internal/trace/transport.go index e5ef0c7eb..ffd139277 100644 --- a/internal/trace/transport.go +++ b/internal/trace/transport.go @@ -94,13 +94,13 @@ func logHeader(header http.Header) string { } return strings.Join(headers, "\n") } - return " " + return " Empty header" } // TODO: test and docs func logResponseBody(resp *http.Response) string { - if resp.Body == nil || resp.ContentLength <= 0 { - return " " + if resp.Body == nil || resp.ContentLength <= 0 || resp.Body == http.NoBody { + return " Empty body" } contentType := resp.Header.Get("Content-Type") if !shouldPrint(contentType) { From fd687a409b3333cd4c88a1612a90dc098833b45c Mon Sep 17 00:00:00 2001 From: "Lixia (Sylvia) Lei" Date: Sat, 30 Nov 2024 23:58:41 +0800 Subject: [PATCH 08/28] minor Signed-off-by: Lixia (Sylvia) Lei --- internal/trace/transport.go | 9 +++++---- 1 file changed, 5 insertions(+), 4 deletions(-) diff --git a/internal/trace/transport.go b/internal/trace/transport.go index ffd139277..66ba36111 100644 --- a/internal/trace/transport.go +++ b/internal/trace/transport.go @@ -100,18 +100,17 @@ func logHeader(header http.Header) string { // TODO: test and docs func logResponseBody(resp *http.Response) string { if resp.Body == nil || resp.ContentLength <= 0 || resp.Body == http.NoBody { - return " Empty body" + return "" } contentType := resp.Header.Get("Content-Type") if !shouldPrint(contentType) { - return " Body of this content type is not printed" + return fmt.Sprintf(" Body of content type \"%s\" is not printed", contentType) } if resp.ContentLength > payloadSizeLimit { - return fmt.Sprintf(" Body larger to %d bytes is not printed", payloadSizeLimit) + return fmt.Sprintf(" Body larger than %d bytes is not printed", payloadSizeLimit) } var builder strings.Builder - // TODO: what if body has been read out? tr := io.TeeReader(resp.Body, &builder) bodyBytes, err := io.ReadAll(tr) if err != nil { @@ -123,9 +122,11 @@ func logResponseBody(resp *http.Response) string { } func shouldPrint(contentType string) bool { + // JSON types if strings.HasPrefix(contentType, "application/json") || strings.HasSuffix(contentType, "+json") { return true } + // text types if strings.HasPrefix(contentType, "text/") { return true } From 06b314d40c49fb7a1fe2dc56d443f8865aabc401 Mon Sep 17 00:00:00 2001 From: "Lixia (Sylvia) Lei" Date: Tue, 3 Dec 2024 17:08:04 +0800 Subject: [PATCH 09/28] minor adjustment Signed-off-by: Lixia (Sylvia) Lei --- internal/trace/context.go | 6 ------ internal/trace/transport.go | 2 +- 2 files changed, 1 insertion(+), 7 deletions(-) diff --git a/internal/trace/context.go b/internal/trace/context.go index 82329bc4a..57a2e472d 100644 --- a/internal/trace/context.go +++ b/internal/trace/context.go @@ -36,12 +36,6 @@ func NewLogger(ctx context.Context, debug bool) (context.Context, logrus.FieldLo } logger := logrus.New() - // logger.SetFormatter(&logrus.TextFormatter{ - // DisableQuote: true, - // FullTimestamp: true, - // DisableLevelTruncation: true, - // ForceColors: true, - // }) logger.SetFormatter(&TextFormatter{}) logger.SetLevel(logLevel) diff --git a/internal/trace/transport.go b/internal/trace/transport.go index 66ba36111..5275f8677 100644 --- a/internal/trace/transport.go +++ b/internal/trace/transport.go @@ -99,7 +99,7 @@ func logHeader(header http.Header) string { // TODO: test and docs func logResponseBody(resp *http.Response) string { - if resp.Body == nil || resp.ContentLength <= 0 || resp.Body == http.NoBody { + if resp.Body == nil || resp.Body == http.NoBody || resp.ContentLength <= 0 { return "" } contentType := resp.Header.Get("Content-Type") From 93d0de19750209751ede65d32cbc74bfe1478326 Mon Sep 17 00:00:00 2001 From: "Lixia (Sylvia) Lei" Date: Tue, 3 Dec 2024 19:30:30 +0800 Subject: [PATCH 10/28] minor refine Signed-off-by: Lixia (Sylvia) Lei --- cmd/oras/root/repo/ls.go | 7 ------- internal/trace/context.go | 1 - internal/trace/text_formatter.go | 1 - internal/trace/transport.go | 8 +++++--- 4 files changed, 5 insertions(+), 12 deletions(-) diff --git a/cmd/oras/root/repo/ls.go b/cmd/oras/root/repo/ls.go index 85fc92d9a..501ee050b 100644 --- a/cmd/oras/root/repo/ls.go +++ b/cmd/oras/root/repo/ls.go @@ -77,13 +77,6 @@ func listRepository(cmd *cobra.Command, opts *repositoryOptions) error { if err != nil { return err } - - // TEST: to be removed - logger = logger.WithField("registry", reg.Reference.Host()) - logger = logger.WithField("testkey", 123) - logger.Info("test info") - logger.Warn("test warn") - err = reg.Repositories(ctx, opts.last, func(repos []string) error { for _, repo := range repos { if subRepo, found := strings.CutPrefix(repo, opts.namespace); found { diff --git a/internal/trace/context.go b/internal/trace/context.go index 57a2e472d..1acf25811 100644 --- a/internal/trace/context.go +++ b/internal/trace/context.go @@ -37,7 +37,6 @@ func NewLogger(ctx context.Context, debug bool) (context.Context, logrus.FieldLo logger := logrus.New() logger.SetFormatter(&TextFormatter{}) - logger.SetLevel(logLevel) entry := logger.WithContext(ctx) return context.WithValue(ctx, loggerKey, entry), entry diff --git a/internal/trace/text_formatter.go b/internal/trace/text_formatter.go index 70bba58ae..bd59641c3 100644 --- a/internal/trace/text_formatter.go +++ b/internal/trace/text_formatter.go @@ -46,6 +46,5 @@ func (f *TextFormatter) Format(entry *logrus.Entry) ([]byte, error) { } buf.WriteString(logEntrySeperator) - return buf.Bytes(), nil } diff --git a/internal/trace/transport.go b/internal/trace/transport.go index 5275f8677..a8cbd8078 100644 --- a/internal/trace/transport.go +++ b/internal/trace/transport.go @@ -97,13 +97,14 @@ func logHeader(header http.Header) string { return " Empty header" } -// TODO: test and docs +// logResponseBody prints out the response body if it is printable and within +// the size limit. func logResponseBody(resp *http.Response) string { if resp.Body == nil || resp.Body == http.NoBody || resp.ContentLength <= 0 { return "" } contentType := resp.Header.Get("Content-Type") - if !shouldPrint(contentType) { + if !isPrintableContentType(contentType) { return fmt.Sprintf(" Body of content type \"%s\" is not printed", contentType) } if resp.ContentLength > payloadSizeLimit { @@ -121,7 +122,8 @@ func logResponseBody(resp *http.Response) string { return builder.String() } -func shouldPrint(contentType string) bool { +// isPrintableContentType returns true if the content of contentType is printable. +func isPrintableContentType(contentType string) bool { // JSON types if strings.HasPrefix(contentType, "application/json") || strings.HasSuffix(contentType, "+json") { return true From 21d52b6bdd18cf934a577bcc68f8abf302b76525 Mon Sep 17 00:00:00 2001 From: "Lixia (Sylvia) Lei" Date: Tue, 3 Dec 2024 20:35:40 +0800 Subject: [PATCH 11/28] add unit tests Signed-off-by: Lixia (Sylvia) Lei --- internal/trace/transport.go | 12 +- internal/trace/transport_test.go | 203 +++++++++++++++++++++++++++++++ 2 files changed, 212 insertions(+), 3 deletions(-) create mode 100644 internal/trace/transport_test.go diff --git a/internal/trace/transport.go b/internal/trace/transport.go index a8cbd8078..d3160370e 100644 --- a/internal/trace/transport.go +++ b/internal/trace/transport.go @@ -36,8 +36,8 @@ var ( } ) +// payloadSizeLimit limits the maximum size of the response body to be printed. const payloadSizeLimit int64 = 4 * 1024 * 1024 // 4 MiB -// const payloadSizeLimit int64 = 8 // TEST // Transport is an http.RoundTripper that keeps track of the in-flight // request and add hooks to report HTTP tracing events. @@ -112,13 +112,19 @@ func logResponseBody(resp *http.Response) string { } var builder strings.Builder - tr := io.TeeReader(resp.Body, &builder) + // It is possible that the actual body size is smaller or larger than the content length. + // In case of smaller, we just print the body and do not error out. + // In case of larger, we only print the part that is within the content length for security consideration. + lr := io.LimitReader(resp.Body, resp.ContentLength) + tr := io.TeeReader(lr, &builder) bodyBytes, err := io.ReadAll(tr) if err != nil { return fmt.Sprintf(" Error reading response body: %v", err) } - resp.Body = io.NopCloser(bytes.NewReader(bodyBytes)) + // Note: if the size of the read body bytes mismatches the content length, + // the subsequent response processing might be broken. + resp.Body = io.NopCloser(bytes.NewReader(bodyBytes)) return builder.String() } diff --git a/internal/trace/transport_test.go b/internal/trace/transport_test.go new file mode 100644 index 000000000..ea6d54433 --- /dev/null +++ b/internal/trace/transport_test.go @@ -0,0 +1,203 @@ +/* +Copyright The ORAS Authors. +Licensed under the Apache License, Version 2.0 (the "License"); +you may not use this file except in compliance with the License. +You may obtain a copy of the License at + +http://www.apache.org/licenses/LICENSE-2.0 + +Unless required by applicable law or agreed to in writing, software +distributed under the License is distributed on an "AS IS" BASIS, +WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +See the License for the specific language governing permissions and +limitations under the License. +*/ + +package trace + +import ( + "fmt" + "io" + "net/http" + "strings" + "testing" +) + +func Test_isPrintableContentType(t *testing.T) { + tests := []struct { + name string + contentType string + want bool + }{ + { + name: "Empty content type", + contentType: "", + want: false, + }, + { + name: "General JSON type", + contentType: "application/json", + want: true, + }, + { + name: "Manifest type in JSON", + contentType: "application/vnd.oci.image.manifest.v1+json", + want: true, + }, + { + name: "Random content type in JSON", + contentType: "application/whatever+json", + want: true, + }, + { + name: "Plain text type", + contentType: "text/plain", + want: true, + }, + { + name: "Plain text type with charset", + contentType: "text/plain; charset=utf-8", + want: true, + }, + { + name: "HTML text type", + contentType: "text/html", + want: true, + }, + { + name: "HTML text type with charset", + contentType: "text/html; charset=utf-8", + want: true, + }, + { + name: "Binary type", + contentType: "application/octet-stream", + want: false, + }, + { + name: "Unknown type", + contentType: "unknown/unknown", + want: false, + }, + { + name: "Invalid type", + contentType: "application/", + want: false, + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + if got := isPrintableContentType(tt.contentType); got != tt.want { + t.Errorf("isPrintableContentType() = %v, want %v", got, tt.want) + } + }) + } +} + +func Test_logResponseBody(t *testing.T) { + tests := []struct { + name string + resp *http.Response + want string + }{ + { + name: "Nil body", + resp: &http.Response{ + Body: nil, + }, + want: "", + }, + { + name: "No body", + resp: &http.Response{ + Body: http.NoBody, + }, + want: "", + }, + { + name: "Empty body", + resp: &http.Response{ + Body: io.NopCloser(strings.NewReader("")), + ContentLength: 0, + }, + want: "", + }, + { + name: "Unknown content length", + resp: &http.Response{ + Body: io.NopCloser(strings.NewReader("whatever")), + ContentLength: -1, + }, + want: "", + }, + { + name: "Non-printable content type", + resp: &http.Response{ + Body: io.NopCloser(strings.NewReader("binary data")), + ContentLength: 10, + Header: http.Header{"Content-Type": []string{"application/octet-stream"}}, + }, + want: " Body of content type \"application/octet-stream\" is not printed", + }, + { + name: "Body larger than limit", + resp: &http.Response{ + Body: io.NopCloser(strings.NewReader(strings.Repeat("a", int(payloadSizeLimit+1)))), + ContentLength: payloadSizeLimit + 1, + Header: http.Header{"Content-Type": []string{"text/plain"}}, + }, + want: fmt.Sprintf(" Body larger than %d bytes is not printed", payloadSizeLimit), + }, + { + name: "Printable content type within limit", + resp: &http.Response{ + Body: io.NopCloser(strings.NewReader("printable data")), + ContentLength: int64(len("printable data")), + Header: http.Header{"Content-Type": []string{"text/plain"}}, + }, + want: "printable data", + }, + { + name: "Actual body size is larger than content length", + resp: &http.Response{ + Body: io.NopCloser(strings.NewReader("data")), + ContentLength: 3, + Header: http.Header{"Content-Type": []string{"text/plain"}}, + }, + want: "dat", + }, + { + name: "Actual body size is smaller than content length", + resp: &http.Response{ + Body: io.NopCloser(strings.NewReader("data")), + ContentLength: 5, + Header: http.Header{"Content-Type": []string{"text/plain"}}, + }, + want: "data", + }, + { + name: "Error reading body", + resp: &http.Response{ + Body: io.NopCloser(&errorReader{}), + ContentLength: 10, + Header: http.Header{"Content-Type": []string{"text/plain"}}, + }, + want: " Error reading response body: mock error", + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + if got := logResponseBody(tt.resp); got != tt.want { + t.Errorf("logResponseBody() = %v, want %v", got, tt.want) + } + }) + } +} + +type errorReader struct{} + +func (e *errorReader) Read(p []byte) (n int, err error) { + return 0, fmt.Errorf("mock error") +} From 48d21e54b806b0d7d2560f842463dd7a28192090 Mon Sep 17 00:00:00 2001 From: "Lixia (Sylvia) Lei" Date: Tue, 3 Dec 2024 20:41:27 +0800 Subject: [PATCH 12/28] fix line ending Signed-off-by: Lixia (Sylvia) Lei --- internal/trace/text_formatter.go | 100 +++++++++++++++---------------- 1 file changed, 50 insertions(+), 50 deletions(-) diff --git a/internal/trace/text_formatter.go b/internal/trace/text_formatter.go index bd59641c3..9f4bfdea0 100644 --- a/internal/trace/text_formatter.go +++ b/internal/trace/text_formatter.go @@ -1,50 +1,50 @@ -/* -Copyright The ORAS Authors. -Licensed under the Apache License, Version 2.0 (the "License"); -you may not use this file except in compliance with the License. -You may obtain a copy of the License at - -http://www.apache.org/licenses/LICENSE-2.0 - -Unless required by applicable law or agreed to in writing, software -distributed under the License is distributed on an "AS IS" BASIS, -WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. -See the License for the specific language governing permissions and -limitations under the License. -*/ - -package trace - -import ( - "bytes" - "fmt" - "strings" - "time" - - "github.com/sirupsen/logrus" -) - -// TextFormatter formats logs into text. -type TextFormatter struct{} - -// logEntrySeperator is the separator between log entries. -const logEntrySeperator = "\n\n" // two empty lines - -// Format renders a single log entry. -func (f *TextFormatter) Format(entry *logrus.Entry) ([]byte, error) { - var buf bytes.Buffer - - timestamp := entry.Time.Format(time.RFC3339Nano) - levelText := strings.ToUpper(entry.Level.String()) - buf.WriteString(fmt.Sprintf("[%s][%s]: %s\n", timestamp, levelText, entry.Message)) - // printing data fields - if len(entry.Data) != 0 { - buf.WriteString("[Data]:\n") - for k, v := range entry.Data { - buf.WriteString(fmt.Sprintf(" %s=%v\n", k, v)) - } - } - - buf.WriteString(logEntrySeperator) - return buf.Bytes(), nil -} +/* +Copyright The ORAS Authors. +Licensed under the Apache License, Version 2.0 (the "License"); +you may not use this file except in compliance with the License. +You may obtain a copy of the License at + +http://www.apache.org/licenses/LICENSE-2.0 + +Unless required by applicable law or agreed to in writing, software +distributed under the License is distributed on an "AS IS" BASIS, +WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +See the License for the specific language governing permissions and +limitations under the License. +*/ + +package trace + +import ( + "bytes" + "fmt" + "strings" + "time" + + "github.com/sirupsen/logrus" +) + +// TextFormatter formats logs into text. +type TextFormatter struct{} + +// logEntrySeperator is the separator between log entries. +const logEntrySeperator = "\n\n" // two empty lines + +// Format renders a single log entry. +func (f *TextFormatter) Format(entry *logrus.Entry) ([]byte, error) { + var buf bytes.Buffer + + timestamp := entry.Time.Format(time.RFC3339Nano) + levelText := strings.ToUpper(entry.Level.String()) + buf.WriteString(fmt.Sprintf("[%s][%s]: %s\n", timestamp, levelText, entry.Message)) + // printing data fields + if len(entry.Data) != 0 { + buf.WriteString("[Data]:\n") + for k, v := range entry.Data { + buf.WriteString(fmt.Sprintf(" %s=%v\n", k, v)) + } + } + + buf.WriteString(logEntrySeperator) + return buf.Bytes(), nil +} From 91968f03d9542fb0e37813613f138616506c14f7 Mon Sep 17 00:00:00 2001 From: "Lixia (Sylvia) Lei" Date: Wed, 4 Dec 2024 11:26:01 +0800 Subject: [PATCH 13/28] update Signed-off-by: Lixia (Sylvia) Lei --- internal/trace/transport.go | 28 ++++++++++++++++++---------- internal/trace/transport_test.go | 27 ++++++++++++++++----------- 2 files changed, 34 insertions(+), 21 deletions(-) diff --git a/internal/trace/transport.go b/internal/trace/transport.go index d3160370e..ab09a5ed7 100644 --- a/internal/trace/transport.go +++ b/internal/trace/transport.go @@ -99,25 +99,33 @@ func logHeader(header http.Header) string { // logResponseBody prints out the response body if it is printable and within // the size limit. +// TODO: review tests func logResponseBody(resp *http.Response) string { - if resp.Body == nil || resp.Body == http.NoBody || resp.ContentLength <= 0 { - return "" + if resp.Body == nil || resp.Body == http.NoBody || resp.ContentLength == 0 { + return " No response body to print" } + contentType := resp.Header.Get("Content-Type") if !isPrintableContentType(contentType) { - return fmt.Sprintf(" Body of content type \"%s\" is not printed", contentType) + return fmt.Sprintf(" Response body of content type \"%s\" is not printed", contentType) + } + if resp.ContentLength < 0 { + return " Response body of unknown content length is not printed" } if resp.ContentLength > payloadSizeLimit { - return fmt.Sprintf(" Body larger than %d bytes is not printed", payloadSizeLimit) + return fmt.Sprintf(" Response body larger than %d bytes is not printed", payloadSizeLimit) } - var builder strings.Builder // It is possible that the actual body size is smaller or larger than the content length. // In case of smaller, we just print the body and do not error out. - // In case of larger, we only print the part that is within the content length for security consideration. - lr := io.LimitReader(resp.Body, resp.ContentLength) - tr := io.TeeReader(lr, &builder) - bodyBytes, err := io.ReadAll(tr) + // In case of larger, we only print the part that is within the limit for security consideration. + limit := payloadSizeLimit + if resp.ContentLength < limit { + limit = resp.ContentLength + } + defer resp.Body.Close() + lr := io.LimitReader(resp.Body, limit) + bodyBytes, err := io.ReadAll(lr) if err != nil { return fmt.Sprintf(" Error reading response body: %v", err) } @@ -125,7 +133,7 @@ func logResponseBody(resp *http.Response) string { // Note: if the size of the read body bytes mismatches the content length, // the subsequent response processing might be broken. resp.Body = io.NopCloser(bytes.NewReader(bodyBytes)) - return builder.String() + return string(bodyBytes) } // isPrintableContentType returns true if the content of contentType is printable. diff --git a/internal/trace/transport_test.go b/internal/trace/transport_test.go index ea6d54433..266d3255b 100644 --- a/internal/trace/transport_test.go +++ b/internal/trace/transport_test.go @@ -104,32 +104,37 @@ func Test_logResponseBody(t *testing.T) { { name: "Nil body", resp: &http.Response{ - Body: nil, + Body: nil, + Header: http.Header{"Content-Type": []string{"application/json"}}, }, - want: "", + want: " No response body to print", }, { name: "No body", resp: &http.Response{ - Body: http.NoBody, + Body: http.NoBody, + ContentLength: 100, + Header: http.Header{"Content-Type": []string{"application/json"}}, }, - want: "", + want: " No response body to print", }, { name: "Empty body", resp: &http.Response{ Body: io.NopCloser(strings.NewReader("")), ContentLength: 0, + Header: http.Header{"Content-Type": []string{"text/plain"}}, }, - want: "", + want: " No response body to print", }, { name: "Unknown content length", resp: &http.Response{ Body: io.NopCloser(strings.NewReader("whatever")), ContentLength: -1, + Header: http.Header{"Content-Type": []string{"text/plain"}}, }, - want: "", + want: " Response body of unknown content length is not printed", }, { name: "Non-printable content type", @@ -138,7 +143,7 @@ func Test_logResponseBody(t *testing.T) { ContentLength: 10, Header: http.Header{"Content-Type": []string{"application/octet-stream"}}, }, - want: " Body of content type \"application/octet-stream\" is not printed", + want: " Response body of content type \"application/octet-stream\" is not printed", }, { name: "Body larger than limit", @@ -147,16 +152,16 @@ func Test_logResponseBody(t *testing.T) { ContentLength: payloadSizeLimit + 1, Header: http.Header{"Content-Type": []string{"text/plain"}}, }, - want: fmt.Sprintf(" Body larger than %d bytes is not printed", payloadSizeLimit), + want: fmt.Sprintf(" Response body larger than %d bytes is not printed", payloadSizeLimit), }, { name: "Printable content type within limit", resp: &http.Response{ - Body: io.NopCloser(strings.NewReader("printable data")), - ContentLength: int64(len("printable data")), + Body: io.NopCloser(strings.NewReader("data")), + ContentLength: int64(len("data")), Header: http.Header{"Content-Type": []string{"text/plain"}}, }, - want: "printable data", + want: "data", }, { name: "Actual body size is larger than content length", From 82ea2d2f18789666cd0243bd7d970077e383b31b Mon Sep 17 00:00:00 2001 From: "Lixia (Sylvia) Lei" Date: Wed, 4 Dec 2024 12:34:34 +0800 Subject: [PATCH 14/28] refine + todos Signed-off-by: Lixia (Sylvia) Lei --- internal/trace/transport.go | 18 ++++++++---------- internal/trace/transport_test.go | 17 +++++++++++++---- 2 files changed, 21 insertions(+), 14 deletions(-) diff --git a/internal/trace/transport.go b/internal/trace/transport.go index ab09a5ed7..fa6f67cf5 100644 --- a/internal/trace/transport.go +++ b/internal/trace/transport.go @@ -100,11 +100,13 @@ func logHeader(header http.Header) string { // logResponseBody prints out the response body if it is printable and within // the size limit. // TODO: review tests +// TODO: what about seek case? func logResponseBody(resp *http.Response) string { if resp.Body == nil || resp.Body == http.NoBody || resp.ContentLength == 0 { return " No response body to print" } + // non-applicable body is not printed and remains untouched for subsequent processing contentType := resp.Header.Get("Content-Type") if !isPrintableContentType(contentType) { return fmt.Sprintf(" Response body of content type \"%s\" is not printed", contentType) @@ -116,22 +118,18 @@ func logResponseBody(resp *http.Response) string { return fmt.Sprintf(" Response body larger than %d bytes is not printed", payloadSizeLimit) } - // It is possible that the actual body size is smaller or larger than the content length. - // In case of smaller, we just print the body and do not error out. - // In case of larger, we only print the part that is within the limit for security consideration. - limit := payloadSizeLimit - if resp.ContentLength < limit { - limit = resp.ContentLength - } + // Note: Even if the actual body size mismatches the content length, we still print the body for debugging purposes. + // If the actual body size exceeds the limit, the body will be truncated to limit. + // In this case, the response processing subsequent to logging might be broken. + // TODO: can we tell the body is truncated? defer resp.Body.Close() - lr := io.LimitReader(resp.Body, limit) + lr := io.LimitReader(resp.Body, payloadSizeLimit) bodyBytes, err := io.ReadAll(lr) if err != nil { return fmt.Sprintf(" Error reading response body: %v", err) } - // Note: if the size of the read body bytes mismatches the content length, - // the subsequent response processing might be broken. + // reset the body for subsequent processing resp.Body = io.NopCloser(bytes.NewReader(bodyBytes)) return string(bodyBytes) } diff --git a/internal/trace/transport_test.go b/internal/trace/transport_test.go index 266d3255b..32e588c8c 100644 --- a/internal/trace/transport_test.go +++ b/internal/trace/transport_test.go @@ -148,7 +148,7 @@ func Test_logResponseBody(t *testing.T) { { name: "Body larger than limit", resp: &http.Response{ - Body: io.NopCloser(strings.NewReader(strings.Repeat("a", int(payloadSizeLimit+1)))), + Body: io.NopCloser(strings.NewReader(strings.Repeat("a", int(payloadSizeLimit+1)))), // 1 byte larger than limit ContentLength: payloadSizeLimit + 1, Header: http.Header{"Content-Type": []string{"text/plain"}}, }, @@ -167,16 +167,25 @@ func Test_logResponseBody(t *testing.T) { name: "Actual body size is larger than content length", resp: &http.Response{ Body: io.NopCloser(strings.NewReader("data")), - ContentLength: 3, + ContentLength: 3, // mismatched content length Header: http.Header{"Content-Type": []string{"text/plain"}}, }, - want: "dat", + want: "data", + }, + { + name: "Actual body size is larger than content length and exceeds limit", + resp: &http.Response{ + Body: io.NopCloser(strings.NewReader(strings.Repeat("a", int(payloadSizeLimit+1)))), // 1 byte larger than limit + ContentLength: 1, // mismatched content length + Header: http.Header{"Content-Type": []string{"text/plain"}}, + }, + want: strings.Repeat("a", int(payloadSizeLimit)), }, { name: "Actual body size is smaller than content length", resp: &http.Response{ Body: io.NopCloser(strings.NewReader("data")), - ContentLength: 5, + ContentLength: 5, // mismatched content length Header: http.Header{"Content-Type": []string{"text/plain"}}, }, want: "data", From 3f9f5e7f59fd7f2dec3ee824c8c223dde62ed1b3 Mon Sep 17 00:00:00 2001 From: "Lixia (Sylvia) Lei" Date: Wed, 4 Dec 2024 15:51:33 +0800 Subject: [PATCH 15/28] refactor tests Signed-off-by: Lixia (Sylvia) Lei --- internal/trace/transport.go | 12 +++++------ internal/trace/transport_test.go | 37 ++++++++++++++++++++------------ 2 files changed, 28 insertions(+), 21 deletions(-) diff --git a/internal/trace/transport.go b/internal/trace/transport.go index fa6f67cf5..fc4eddc98 100644 --- a/internal/trace/transport.go +++ b/internal/trace/transport.go @@ -99,8 +99,6 @@ func logHeader(header http.Header) string { // logResponseBody prints out the response body if it is printable and within // the size limit. -// TODO: review tests -// TODO: what about seek case? func logResponseBody(resp *http.Response) string { if resp.Body == nil || resp.Body == http.NoBody || resp.ContentLength == 0 { return " No response body to print" @@ -118,12 +116,12 @@ func logResponseBody(resp *http.Response) string { return fmt.Sprintf(" Response body larger than %d bytes is not printed", payloadSizeLimit) } - // Note: Even if the actual body size mismatches the content length, we still print the body for debugging purposes. - // If the actual body size exceeds the limit, the body will be truncated to limit. + // Note: If the actual body size mismatches the content length and exceeds the limit, + // the body will be truncated to the limit for seucrity consideration. // In this case, the response processing subsequent to logging might be broken. - // TODO: can we tell the body is truncated? - defer resp.Body.Close() - lr := io.LimitReader(resp.Body, payloadSizeLimit) + rc := resp.Body + defer rc.Close() + lr := io.LimitReader(rc, payloadSizeLimit) bodyBytes, err := io.ReadAll(lr) if err != nil { return fmt.Sprintf(" Error reading response body: %v", err) diff --git a/internal/trace/transport_test.go b/internal/trace/transport_test.go index 32e588c8c..45ba22f46 100644 --- a/internal/trace/transport_test.go +++ b/internal/trace/transport_test.go @@ -16,10 +16,10 @@ limitations under the License. package trace import ( + "bytes" "fmt" "io" "net/http" - "strings" "testing" ) @@ -113,7 +113,7 @@ func Test_logResponseBody(t *testing.T) { name: "No body", resp: &http.Response{ Body: http.NoBody, - ContentLength: 100, + ContentLength: 100, // in case of HEAD response, the content length is set but the body is empty Header: http.Header{"Content-Type": []string{"application/json"}}, }, want: " No response body to print", @@ -121,7 +121,7 @@ func Test_logResponseBody(t *testing.T) { { name: "Empty body", resp: &http.Response{ - Body: io.NopCloser(strings.NewReader("")), + Body: io.NopCloser(bytes.NewReader([]byte(""))), ContentLength: 0, Header: http.Header{"Content-Type": []string{"text/plain"}}, }, @@ -130,7 +130,7 @@ func Test_logResponseBody(t *testing.T) { { name: "Unknown content length", resp: &http.Response{ - Body: io.NopCloser(strings.NewReader("whatever")), + Body: io.NopCloser(bytes.NewReader([]byte("whatever"))), ContentLength: -1, Header: http.Header{"Content-Type": []string{"text/plain"}}, }, @@ -139,16 +139,25 @@ func Test_logResponseBody(t *testing.T) { { name: "Non-printable content type", resp: &http.Response{ - Body: io.NopCloser(strings.NewReader("binary data")), - ContentLength: 10, + Body: io.NopCloser(bytes.NewReader([]byte("binary data"))), + ContentLength: 11, Header: http.Header{"Content-Type": []string{"application/octet-stream"}}, }, want: " Response body of content type \"application/octet-stream\" is not printed", }, + { + name: "Body at the limit", + resp: &http.Response{ + Body: io.NopCloser(bytes.NewReader(bytes.Repeat([]byte("a"), int(payloadSizeLimit)))), // 1 byte larger than limit + ContentLength: payloadSizeLimit, + Header: http.Header{"Content-Type": []string{"text/plain"}}, + }, + want: string(bytes.Repeat([]byte("a"), int(payloadSizeLimit))), + }, { name: "Body larger than limit", resp: &http.Response{ - Body: io.NopCloser(strings.NewReader(strings.Repeat("a", int(payloadSizeLimit+1)))), // 1 byte larger than limit + Body: io.NopCloser(bytes.NewReader(bytes.Repeat([]byte("a"), int(payloadSizeLimit+1)))), // 1 byte larger than limit ContentLength: payloadSizeLimit + 1, Header: http.Header{"Content-Type": []string{"text/plain"}}, }, @@ -157,8 +166,8 @@ func Test_logResponseBody(t *testing.T) { { name: "Printable content type within limit", resp: &http.Response{ - Body: io.NopCloser(strings.NewReader("data")), - ContentLength: int64(len("data")), + Body: io.NopCloser(bytes.NewReader([]byte("data"))), + ContentLength: 4, Header: http.Header{"Content-Type": []string{"text/plain"}}, }, want: "data", @@ -166,7 +175,7 @@ func Test_logResponseBody(t *testing.T) { { name: "Actual body size is larger than content length", resp: &http.Response{ - Body: io.NopCloser(strings.NewReader("data")), + Body: io.NopCloser(bytes.NewReader([]byte("data"))), ContentLength: 3, // mismatched content length Header: http.Header{"Content-Type": []string{"text/plain"}}, }, @@ -175,16 +184,16 @@ func Test_logResponseBody(t *testing.T) { { name: "Actual body size is larger than content length and exceeds limit", resp: &http.Response{ - Body: io.NopCloser(strings.NewReader(strings.Repeat("a", int(payloadSizeLimit+1)))), // 1 byte larger than limit - ContentLength: 1, // mismatched content length + Body: io.NopCloser(bytes.NewReader(bytes.Repeat([]byte("a"), int(payloadSizeLimit+1)))), // 1 byte larger than limit + ContentLength: 1, // mismatched content length Header: http.Header{"Content-Type": []string{"text/plain"}}, }, - want: strings.Repeat("a", int(payloadSizeLimit)), + want: string(bytes.Repeat([]byte("a"), int(payloadSizeLimit))), }, { name: "Actual body size is smaller than content length", resp: &http.Response{ - Body: io.NopCloser(strings.NewReader("data")), + Body: io.NopCloser(bytes.NewReader([]byte("data"))), ContentLength: 5, // mismatched content length Header: http.Header{"Content-Type": []string{"text/plain"}}, }, From 6fd2ed8f1f8f0333d57fcb4a575cfe1446d57903 Mon Sep 17 00:00:00 2001 From: "Lixia (Sylvia) Lei" Date: Wed, 4 Dec 2024 16:02:49 +0800 Subject: [PATCH 16/28] remove test code Signed-off-by: Lixia (Sylvia) Lei --- internal/trace/transport.go | 4 ---- 1 file changed, 4 deletions(-) diff --git a/internal/trace/transport.go b/internal/trace/transport.go index fc4eddc98..329cae355 100644 --- a/internal/trace/transport.go +++ b/internal/trace/transport.go @@ -58,10 +58,6 @@ func (t *Transport) RoundTrip(req *http.Request) (resp *http.Response, err error ctx := req.Context() e := Logger(ctx) - // TEST: to be removed - e = e.WithField("host", req.Host) - e = e.WithField("testkey", 123) - // log the request e.Debugf("--> Request #%d\n> Request URL: %q\n> Request method: %q\n> Request headers:\n%s", id, req.URL, req.Method, logHeader(req.Header)) From 10356035157c15d48dbd947bc27915aa63da51c9 Mon Sep 17 00:00:00 2001 From: "Lixia (Sylvia) Lei" Date: Wed, 4 Dec 2024 18:30:22 +0800 Subject: [PATCH 17/28] add unit test Signed-off-by: Lixia (Sylvia) Lei --- internal/trace/text_formatter_test.go | 99 +++++++++++++++++++++++++++ 1 file changed, 99 insertions(+) create mode 100644 internal/trace/text_formatter_test.go diff --git a/internal/trace/text_formatter_test.go b/internal/trace/text_formatter_test.go new file mode 100644 index 000000000..c7ac5b9c1 --- /dev/null +++ b/internal/trace/text_formatter_test.go @@ -0,0 +1,99 @@ +/* +Copyright The ORAS Authors. +Licensed under the Apache License, Version 2.0 (the "License"); +you may not use this file except in compliance with the License. +You may obtain a copy of the License at + +http://www.apache.org/licenses/LICENSE-2.0 + +Unless required by applicable law or agreed to in writing, software +distributed under the License is distributed on an "AS IS" BASIS, +WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +See the License for the specific language governing permissions and +limitations under the License. +*/ + +package trace + +import ( + "reflect" + "testing" + "time" + + "github.com/sirupsen/logrus" +) + +func TestTextFormatter_Format(t *testing.T) { + tests := []struct { + name string + f *TextFormatter + entry *logrus.Entry + want []byte + wantErr bool + }{ + { + name: "debug log entry", + f: &TextFormatter{}, + entry: &logrus.Entry{ + Time: time.Date(2024, time.December, 1, 23, 30, 1, 55, time.UTC), + Level: logrus.DebugLevel, + Message: "test debug", + Data: logrus.Fields{}, + }, + want: []byte("[2024-12-01T23:30:01.000000055Z][DEBUG]: test debug\n\n\n"), + wantErr: false, + }, + { + name: "info log entry", + f: &TextFormatter{}, + entry: &logrus.Entry{ + Time: time.Date(2024, time.December, 1, 23, 30, 1, 55, time.UTC), + Level: logrus.InfoLevel, + Message: "test info", + Data: logrus.Fields{}, + }, + want: []byte("[2024-12-01T23:30:01.000000055Z][INFO]: test info\n\n\n"), + wantErr: false, + }, + { + name: "warning log entry with data fields", + f: &TextFormatter{}, + entry: &logrus.Entry{ + Time: time.Date(2024, time.December, 1, 23, 30, 1, 55, time.UTC), + Level: logrus.WarnLevel, + Message: "test warning with fields", + Data: logrus.Fields{ + "testkey": "testval", + }, + }, + want: []byte("[2024-12-01T23:30:01.000000055Z][WARNING]: test warning with fields\n[Data]:\n testkey=testval\n\n\n"), + wantErr: false, + }, + { + name: "error log entry with data fields", + f: &TextFormatter{}, + entry: &logrus.Entry{ + Time: time.Date(2024, time.December, 1, 23, 30, 1, 55, time.UTC), + Level: logrus.ErrorLevel, + Message: "test warning with fields", + Data: logrus.Fields{ + "testkey": 123, + }, + }, + want: []byte("[2024-12-01T23:30:01.000000055Z][ERROR]: test warning with fields\n[Data]:\n testkey=123\n\n\n"), + wantErr: false, + }, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + got, err := tt.f.Format(tt.entry) + if (err != nil) != tt.wantErr { + t.Errorf("TextFormatter.Format() error = %v, wantErr %v", err, tt.wantErr) + return + } + if !reflect.DeepEqual(got, tt.want) { + t.Errorf("TextFormatter.Format() = %s, want %s", got, tt.want) + } + }) + } +} From 262a57a7f955dc77bb8673c3649a7a785786ab56 Mon Sep 17 00:00:00 2001 From: "Lixia (Sylvia) Lei" Date: Thu, 5 Dec 2024 13:06:28 +0800 Subject: [PATCH 18/28] fix isPrintableContentType() Signed-off-by: Lixia (Sylvia) Lei --- internal/trace/transport.go | 14 +++++++++---- internal/trace/transport_test.go | 34 +++++++++++++++++++++++++------- 2 files changed, 37 insertions(+), 11 deletions(-) diff --git a/internal/trace/transport.go b/internal/trace/transport.go index 329cae355..3fbabc678 100644 --- a/internal/trace/transport.go +++ b/internal/trace/transport.go @@ -19,6 +19,7 @@ import ( "bytes" "fmt" "io" + "mime" "net/http" "strings" "sync/atomic" @@ -130,12 +131,17 @@ func logResponseBody(resp *http.Response) string { // isPrintableContentType returns true if the content of contentType is printable. func isPrintableContentType(contentType string) bool { - // JSON types - if strings.HasPrefix(contentType, "application/json") || strings.HasSuffix(contentType, "+json") { + mediaType, _, err := mime.ParseMediaType(contentType) + if err != nil { + return false + } + + if mediaType == "application/json" || strings.HasSuffix(mediaType, "+json") { + // JSON types return true } - // text types - if strings.HasPrefix(contentType, "text/") { + if mediaType == "text/plain" { + // text types return true } return false diff --git a/internal/trace/transport_test.go b/internal/trace/transport_test.go index 45ba22f46..36b4b232f 100644 --- a/internal/trace/transport_test.go +++ b/internal/trace/transport_test.go @@ -39,11 +39,26 @@ func Test_isPrintableContentType(t *testing.T) { contentType: "application/json", want: true, }, + { + name: "General JSON type with charset", + contentType: "application/json; charset=utf-8", + want: true, + }, + { + name: "Random type with application/json prefix", + contentType: "application/jsonwhatever", + want: false, + }, { name: "Manifest type in JSON", contentType: "application/vnd.oci.image.manifest.v1+json", want: true, }, + { + name: "Manifest type in JSON with charset", + contentType: "application/vnd.oci.image.manifest.v1+json; charset=utf-8", + want: true, + }, { name: "Random content type in JSON", contentType: "application/whatever+json", @@ -60,14 +75,14 @@ func Test_isPrintableContentType(t *testing.T) { want: true, }, { - name: "HTML text type", - contentType: "text/html", - want: true, + name: "Random type with text/plain prefix", + contentType: "text/plainnnnn", + want: false, }, { - name: "HTML text type with charset", - contentType: "text/html; charset=utf-8", - want: true, + name: "HTML type", + contentType: "text/html", + want: false, }, { name: "Binary type", @@ -81,7 +96,12 @@ func Test_isPrintableContentType(t *testing.T) { }, { name: "Invalid type", - contentType: "application/", + contentType: "text/", + want: false, + }, + { + name: "Random string", + contentType: "random123!@#", want: false, }, } From 867f0495016185af23ca82abfeb2cb24404199e2 Mon Sep 17 00:00:00 2001 From: "Lixia (Sylvia) Lei" Date: Thu, 5 Dec 2024 14:37:44 +0800 Subject: [PATCH 19/28] refactor per comments Signed-off-by: Lixia (Sylvia) Lei --- internal/trace/transport.go | 30 +++++++++++++----------------- internal/trace/transport_test.go | 8 ++++---- 2 files changed, 17 insertions(+), 21 deletions(-) diff --git a/internal/trace/transport.go b/internal/trace/transport.go index 3fbabc678..2ab827bfc 100644 --- a/internal/trace/transport.go +++ b/internal/trace/transport.go @@ -97,7 +97,7 @@ func logHeader(header http.Header) string { // logResponseBody prints out the response body if it is printable and within // the size limit. func logResponseBody(resp *http.Response) string { - if resp.Body == nil || resp.Body == http.NoBody || resp.ContentLength == 0 { + if resp.Body == nil || resp.Body == http.NoBody { return " No response body to print" } @@ -106,27 +106,23 @@ func logResponseBody(resp *http.Response) string { if !isPrintableContentType(contentType) { return fmt.Sprintf(" Response body of content type \"%s\" is not printed", contentType) } - if resp.ContentLength < 0 { - return " Response body of unknown content length is not printed" - } - if resp.ContentLength > payloadSizeLimit { - return fmt.Sprintf(" Response body larger than %d bytes is not printed", payloadSizeLimit) - } - // Note: If the actual body size mismatches the content length and exceeds the limit, - // the body will be truncated to the limit for seucrity consideration. - // In this case, the response processing subsequent to logging might be broken. - rc := resp.Body - defer rc.Close() - lr := io.LimitReader(rc, payloadSizeLimit) - bodyBytes, err := io.ReadAll(lr) + // read the body up to limit+1 to check if the body exceeds the limit + lr := io.LimitReader(resp.Body, payloadSizeLimit+1) + readBody, err := io.ReadAll(lr) if err != nil { return fmt.Sprintf(" Error reading response body: %v", err) } + // restore the body by concatenating the read body with the remaining body + resp.Body = io.NopCloser(io.MultiReader(bytes.NewReader(readBody), resp.Body)) - // reset the body for subsequent processing - resp.Body = io.NopCloser(bytes.NewReader(bodyBytes)) - return string(bodyBytes) + if len(readBody) == 0 { + return " Response body is empty" + } + if len(readBody) > int(payloadSizeLimit) { + return string(readBody[:payloadSizeLimit]) + "\n...(truncated)" + } + return string(readBody) } // isPrintableContentType returns true if the content of contentType is printable. diff --git a/internal/trace/transport_test.go b/internal/trace/transport_test.go index 36b4b232f..42c9a3db6 100644 --- a/internal/trace/transport_test.go +++ b/internal/trace/transport_test.go @@ -145,7 +145,7 @@ func Test_logResponseBody(t *testing.T) { ContentLength: 0, Header: http.Header{"Content-Type": []string{"text/plain"}}, }, - want: " No response body to print", + want: " Response body is empty", }, { name: "Unknown content length", @@ -154,7 +154,7 @@ func Test_logResponseBody(t *testing.T) { ContentLength: -1, Header: http.Header{"Content-Type": []string{"text/plain"}}, }, - want: " Response body of unknown content length is not printed", + want: "whatever", }, { name: "Non-printable content type", @@ -181,7 +181,7 @@ func Test_logResponseBody(t *testing.T) { ContentLength: payloadSizeLimit + 1, Header: http.Header{"Content-Type": []string{"text/plain"}}, }, - want: fmt.Sprintf(" Response body larger than %d bytes is not printed", payloadSizeLimit), + want: string(bytes.Repeat([]byte("a"), int(payloadSizeLimit))) + "\n...(truncated)", }, { name: "Printable content type within limit", @@ -208,7 +208,7 @@ func Test_logResponseBody(t *testing.T) { ContentLength: 1, // mismatched content length Header: http.Header{"Content-Type": []string{"text/plain"}}, }, - want: string(bytes.Repeat([]byte("a"), int(payloadSizeLimit))), + want: string(bytes.Repeat([]byte("a"), int(payloadSizeLimit))) + "\n...(truncated)", }, { name: "Actual body size is smaller than content length", From a48b1a7abbf08a700f02b58cccdd2def6324a946 Mon Sep 17 00:00:00 2001 From: "Lixia (Sylvia) Lei" Date: Thu, 5 Dec 2024 14:45:14 +0800 Subject: [PATCH 20/28] improve Signed-off-by: Lixia (Sylvia) Lei --- internal/trace/text_formatter.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/internal/trace/text_formatter.go b/internal/trace/text_formatter.go index 9f4bfdea0..bb6e2de46 100644 --- a/internal/trace/text_formatter.go +++ b/internal/trace/text_formatter.go @@ -36,12 +36,12 @@ func (f *TextFormatter) Format(entry *logrus.Entry) ([]byte, error) { timestamp := entry.Time.Format(time.RFC3339Nano) levelText := strings.ToUpper(entry.Level.String()) - buf.WriteString(fmt.Sprintf("[%s][%s]: %s\n", timestamp, levelText, entry.Message)) + fmt.Fprintf(&buf, "[%s][%s]: %s\n", timestamp, levelText, entry.Message) // printing data fields if len(entry.Data) != 0 { buf.WriteString("[Data]:\n") for k, v := range entry.Data { - buf.WriteString(fmt.Sprintf(" %s=%v\n", k, v)) + fmt.Fprintf(&buf, " %s=%v\n", k, v) } } From 389c632b71c091191e5cdaae75a273f46ad421db Mon Sep 17 00:00:00 2001 From: "Lixia (Sylvia) Lei" Date: Thu, 5 Dec 2024 15:02:10 +0800 Subject: [PATCH 21/28] micro fix Signed-off-by: Lixia (Sylvia) Lei --- internal/trace/text_formatter.go | 4 ++-- internal/trace/transport_test.go | 2 +- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/internal/trace/text_formatter.go b/internal/trace/text_formatter.go index bb6e2de46..9c6472464 100644 --- a/internal/trace/text_formatter.go +++ b/internal/trace/text_formatter.go @@ -37,8 +37,8 @@ func (f *TextFormatter) Format(entry *logrus.Entry) ([]byte, error) { timestamp := entry.Time.Format(time.RFC3339Nano) levelText := strings.ToUpper(entry.Level.String()) fmt.Fprintf(&buf, "[%s][%s]: %s\n", timestamp, levelText, entry.Message) - // printing data fields - if len(entry.Data) != 0 { + // print data fields + if len(entry.Data) > 0 { buf.WriteString("[Data]:\n") for k, v := range entry.Data { fmt.Fprintf(&buf, " %s=%v\n", k, v) diff --git a/internal/trace/transport_test.go b/internal/trace/transport_test.go index 42c9a3db6..5f267d9ba 100644 --- a/internal/trace/transport_test.go +++ b/internal/trace/transport_test.go @@ -168,7 +168,7 @@ func Test_logResponseBody(t *testing.T) { { name: "Body at the limit", resp: &http.Response{ - Body: io.NopCloser(bytes.NewReader(bytes.Repeat([]byte("a"), int(payloadSizeLimit)))), // 1 byte larger than limit + Body: io.NopCloser(bytes.NewReader(bytes.Repeat([]byte("a"), int(payloadSizeLimit)))), ContentLength: payloadSizeLimit, Header: http.Header{"Content-Type": []string{"text/plain"}}, }, From a37fca08267968f3fc71012b74dbc54c9cf02497 Mon Sep 17 00:00:00 2001 From: "Lixia (Sylvia) Lei" Date: Thu, 5 Dec 2024 16:45:09 +0800 Subject: [PATCH 22/28] fix Signed-off-by: Lixia (Sylvia) Lei --- internal/trace/transport.go | 21 ++++- internal/trace/transport_test.go | 141 +++++++++++++++++++++++++++---- 2 files changed, 145 insertions(+), 17 deletions(-) diff --git a/internal/trace/transport.go b/internal/trace/transport.go index 2ab827bfc..13a088b7c 100644 --- a/internal/trace/transport.go +++ b/internal/trace/transport.go @@ -38,7 +38,7 @@ var ( ) // payloadSizeLimit limits the maximum size of the response body to be printed. -const payloadSizeLimit int64 = 4 * 1024 * 1024 // 4 MiB +const payloadSizeLimit int64 = 4 * 1024 // 4 KiB // Transport is an http.RoundTripper that keeps track of the in-flight // request and add hooks to report HTTP tracing events. @@ -113,8 +113,13 @@ func logResponseBody(resp *http.Response) string { if err != nil { return fmt.Sprintf(" Error reading response body: %v", err) } + // restore the body by concatenating the read body with the remaining body - resp.Body = io.NopCloser(io.MultiReader(bytes.NewReader(readBody), resp.Body)) + closeFunc := resp.Body.Close + resp.Body = &readCloser{ + Reader: io.MultiReader(bytes.NewReader(readBody), resp.Body), + closeFunc: closeFunc, + } if len(readBody) == 0 { return " Response body is empty" @@ -142,3 +147,15 @@ func isPrintableContentType(contentType string) bool { } return false } + +// readCloser returns an io.ReadCloser that wraps an io.Reader and a +// close function. +type readCloser struct { + io.Reader + closeFunc func() error +} + +// Close closes the readCloser. +func (rc *readCloser) Close() error { + return rc.closeFunc() +} diff --git a/internal/trace/transport_test.go b/internal/trace/transport_test.go index 5f267d9ba..3fc348ec4 100644 --- a/internal/trace/transport_test.go +++ b/internal/trace/transport_test.go @@ -17,12 +17,17 @@ package trace import ( "bytes" - "fmt" + "errors" "io" "net/http" "testing" ) +var ( + mockReadErr = errors.New("mock read error") + mockCloseErr = errors.New("mock close error") +) + func Test_isPrintableContentType(t *testing.T) { tests := []struct { name string @@ -117,9 +122,10 @@ func Test_isPrintableContentType(t *testing.T) { func Test_logResponseBody(t *testing.T) { tests := []struct { - name string - resp *http.Response - want string + name string + resp *http.Response + want string + wantData []byte }{ { name: "Nil body", @@ -130,7 +136,8 @@ func Test_logResponseBody(t *testing.T) { want: " No response body to print", }, { - name: "No body", + name: "No body", + wantData: nil, resp: &http.Response{ Body: http.NoBody, ContentLength: 100, // in case of HEAD response, the content length is set but the body is empty @@ -139,7 +146,8 @@ func Test_logResponseBody(t *testing.T) { want: " No response body to print", }, { - name: "Empty body", + name: "Empty body", + wantData: []byte(""), resp: &http.Response{ Body: io.NopCloser(bytes.NewReader([]byte(""))), ContentLength: 0, @@ -148,7 +156,8 @@ func Test_logResponseBody(t *testing.T) { want: " Response body is empty", }, { - name: "Unknown content length", + name: "Unknown content length", + wantData: []byte("whatever"), resp: &http.Response{ Body: io.NopCloser(bytes.NewReader([]byte("whatever"))), ContentLength: -1, @@ -157,7 +166,8 @@ func Test_logResponseBody(t *testing.T) { want: "whatever", }, { - name: "Non-printable content type", + name: "Non-printable content type", + wantData: []byte("binary data"), resp: &http.Response{ Body: io.NopCloser(bytes.NewReader([]byte("binary data"))), ContentLength: 11, @@ -166,7 +176,8 @@ func Test_logResponseBody(t *testing.T) { want: " Response body of content type \"application/octet-stream\" is not printed", }, { - name: "Body at the limit", + name: "Body at the limit", + wantData: bytes.Repeat([]byte("a"), int(payloadSizeLimit)), resp: &http.Response{ Body: io.NopCloser(bytes.NewReader(bytes.Repeat([]byte("a"), int(payloadSizeLimit)))), ContentLength: payloadSizeLimit, @@ -175,7 +186,8 @@ func Test_logResponseBody(t *testing.T) { want: string(bytes.Repeat([]byte("a"), int(payloadSizeLimit))), }, { - name: "Body larger than limit", + name: "Body larger than limit", + wantData: bytes.Repeat([]byte("a"), int(payloadSizeLimit+1)), resp: &http.Response{ Body: io.NopCloser(bytes.NewReader(bytes.Repeat([]byte("a"), int(payloadSizeLimit+1)))), // 1 byte larger than limit ContentLength: payloadSizeLimit + 1, @@ -184,7 +196,8 @@ func Test_logResponseBody(t *testing.T) { want: string(bytes.Repeat([]byte("a"), int(payloadSizeLimit))) + "\n...(truncated)", }, { - name: "Printable content type within limit", + name: "Printable content type within limit", + wantData: []byte("data"), resp: &http.Response{ Body: io.NopCloser(bytes.NewReader([]byte("data"))), ContentLength: 4, @@ -193,7 +206,8 @@ func Test_logResponseBody(t *testing.T) { want: "data", }, { - name: "Actual body size is larger than content length", + name: "Actual body size is larger than content length", + wantData: []byte("data"), resp: &http.Response{ Body: io.NopCloser(bytes.NewReader([]byte("data"))), ContentLength: 3, // mismatched content length @@ -202,7 +216,8 @@ func Test_logResponseBody(t *testing.T) { want: "data", }, { - name: "Actual body size is larger than content length and exceeds limit", + name: "Actual body size is larger than content length and exceeds limit", + wantData: bytes.Repeat([]byte("a"), int(payloadSizeLimit+1)), resp: &http.Response{ Body: io.NopCloser(bytes.NewReader(bytes.Repeat([]byte("a"), int(payloadSizeLimit+1)))), // 1 byte larger than limit ContentLength: 1, // mismatched content length @@ -211,7 +226,8 @@ func Test_logResponseBody(t *testing.T) { want: string(bytes.Repeat([]byte("a"), int(payloadSizeLimit))) + "\n...(truncated)", }, { - name: "Actual body size is smaller than content length", + name: "Actual body size is smaller than content length", + wantData: []byte("data"), resp: &http.Response{ Body: io.NopCloser(bytes.NewReader([]byte("data"))), ContentLength: 5, // mismatched content length @@ -219,6 +235,36 @@ func Test_logResponseBody(t *testing.T) { }, want: "data", }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + if got := logResponseBody(tt.resp); got != tt.want { + t.Errorf("logResponseBody() = %v, want %v", got, tt.want) + } + // validate the response body + if tt.resp.Body != nil { + readBytes, err := io.ReadAll(tt.resp.Body) + if err != nil { + t.Errorf("failed to read body after logResponseBody(), err= %v", err) + } + if !bytes.Equal(readBytes, tt.wantData) { + t.Errorf("resp.Body after logResponseBody() = %v, want %v", readBytes, tt.wantData) + } + if closeErr := tt.resp.Body.Close(); closeErr != nil { + t.Errorf("failed to close body after logResponseBody(), err= %v", closeErr) + } + } + }) + } +} + +func Test_logResponseBody_error(t *testing.T) { + tests := []struct { + name string + resp *http.Response + want string + }{ { name: "Error reading body", resp: &http.Response{ @@ -235,6 +281,71 @@ func Test_logResponseBody(t *testing.T) { if got := logResponseBody(tt.resp); got != tt.want { t.Errorf("logResponseBody() = %v, want %v", got, tt.want) } + if closeErr := tt.resp.Body.Close(); closeErr != nil { + t.Errorf("failed to close body after logResponseBody(), err= %v", closeErr) + } + }) + } +} + +func Test_readCloser_Close(t *testing.T) { + + tests := []struct { + name string + reader io.Reader + closeFunc func() error + wantData []byte + wantReadErr error + wantCloseErr error + }{ + { + name: "successfully read and close", + wantData: []byte("data"), + reader: bytes.NewReader([]byte("data")), + closeFunc: func() error { + return nil + }, + wantReadErr: nil, + wantCloseErr: nil, + }, + { + name: "error reading", + wantData: nil, + reader: &errorReader{}, + closeFunc: func() error { + return nil + }, + wantReadErr: mockReadErr, + wantCloseErr: nil, + }, + { + name: "error closing", + wantData: []byte("data"), + reader: bytes.NewReader([]byte("data")), + closeFunc: func() error { + return mockCloseErr + }, + wantReadErr: nil, + wantCloseErr: mockCloseErr, + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + rc := &readCloser{ + Reader: tt.reader, + closeFunc: tt.closeFunc, + } + got, err := io.ReadAll(rc) + if err != tt.wantReadErr { + t.Errorf("readCloser.ReadAll() error = %v, wantErr %v", err, tt.wantReadErr) + } + if !bytes.Equal(got, tt.wantData) { + t.Errorf("readCloser.ReadAll() = %v, want %v", got, tt.wantData) + } + if err := rc.Close(); err != tt.wantCloseErr { + t.Errorf("readCloser.Close() error = %v, wantErr %v", err, tt.wantCloseErr) + } }) } } @@ -242,5 +353,5 @@ func Test_logResponseBody(t *testing.T) { type errorReader struct{} func (e *errorReader) Read(p []byte) (n int, err error) { - return 0, fmt.Errorf("mock error") + return 0, mockReadErr } From 37dc3667ae19cc5b58560a55a05e77bed0f733d3 Mon Sep 17 00:00:00 2001 From: "Lixia (Sylvia) Lei" Date: Thu, 5 Dec 2024 16:49:43 +0800 Subject: [PATCH 23/28] fix test Signed-off-by: Lixia (Sylvia) Lei --- internal/trace/transport_test.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/internal/trace/transport_test.go b/internal/trace/transport_test.go index 3fc348ec4..9cefdd9b2 100644 --- a/internal/trace/transport_test.go +++ b/internal/trace/transport_test.go @@ -272,7 +272,7 @@ func Test_logResponseBody_error(t *testing.T) { ContentLength: 10, Header: http.Header{"Content-Type": []string{"text/plain"}}, }, - want: " Error reading response body: mock error", + want: " Error reading response body: mock read error", }, } From 9303897c21eb27d55ac9c15d8a0ea90fd13d0c55 Mon Sep 17 00:00:00 2001 From: "Lixia (Sylvia) Lei" Date: Fri, 6 Dec 2024 15:58:48 +0800 Subject: [PATCH 24/28] address comment Signed-off-by: Lixia (Sylvia) Lei --- internal/trace/transport.go | 34 ++++++---------- internal/trace/transport_test.go | 67 +------------------------------- 2 files changed, 13 insertions(+), 88 deletions(-) diff --git a/internal/trace/transport.go b/internal/trace/transport.go index 13a088b7c..540373dd0 100644 --- a/internal/trace/transport.go +++ b/internal/trace/transport.go @@ -107,20 +107,22 @@ func logResponseBody(resp *http.Response) string { return fmt.Sprintf(" Response body of content type \"%s\" is not printed", contentType) } + buf := bytes.NewBuffer(nil) + body := resp.Body + // restore the body by concatenating the read body with the remaining body + resp.Body = struct { + io.Reader + io.Closer + }{ + Reader: io.MultiReader(buf, body), + Closer: body, + } // read the body up to limit+1 to check if the body exceeds the limit - lr := io.LimitReader(resp.Body, payloadSizeLimit+1) - readBody, err := io.ReadAll(lr) - if err != nil { + if _, err := io.CopyN(buf, body, payloadSizeLimit+1); err != nil && err != io.EOF { return fmt.Sprintf(" Error reading response body: %v", err) } - // restore the body by concatenating the read body with the remaining body - closeFunc := resp.Body.Close - resp.Body = &readCloser{ - Reader: io.MultiReader(bytes.NewReader(readBody), resp.Body), - closeFunc: closeFunc, - } - + readBody := buf.Bytes() if len(readBody) == 0 { return " Response body is empty" } @@ -147,15 +149,3 @@ func isPrintableContentType(contentType string) bool { } return false } - -// readCloser returns an io.ReadCloser that wraps an io.Reader and a -// close function. -type readCloser struct { - io.Reader - closeFunc func() error -} - -// Close closes the readCloser. -func (rc *readCloser) Close() error { - return rc.closeFunc() -} diff --git a/internal/trace/transport_test.go b/internal/trace/transport_test.go index 9cefdd9b2..2b3376dd2 100644 --- a/internal/trace/transport_test.go +++ b/internal/trace/transport_test.go @@ -23,10 +23,7 @@ import ( "testing" ) -var ( - mockReadErr = errors.New("mock read error") - mockCloseErr = errors.New("mock close error") -) +var mockReadErr = errors.New("mock read error") func Test_isPrintableContentType(t *testing.T) { tests := []struct { @@ -288,68 +285,6 @@ func Test_logResponseBody_error(t *testing.T) { } } -func Test_readCloser_Close(t *testing.T) { - - tests := []struct { - name string - reader io.Reader - closeFunc func() error - wantData []byte - wantReadErr error - wantCloseErr error - }{ - { - name: "successfully read and close", - wantData: []byte("data"), - reader: bytes.NewReader([]byte("data")), - closeFunc: func() error { - return nil - }, - wantReadErr: nil, - wantCloseErr: nil, - }, - { - name: "error reading", - wantData: nil, - reader: &errorReader{}, - closeFunc: func() error { - return nil - }, - wantReadErr: mockReadErr, - wantCloseErr: nil, - }, - { - name: "error closing", - wantData: []byte("data"), - reader: bytes.NewReader([]byte("data")), - closeFunc: func() error { - return mockCloseErr - }, - wantReadErr: nil, - wantCloseErr: mockCloseErr, - }, - } - - for _, tt := range tests { - t.Run(tt.name, func(t *testing.T) { - rc := &readCloser{ - Reader: tt.reader, - closeFunc: tt.closeFunc, - } - got, err := io.ReadAll(rc) - if err != tt.wantReadErr { - t.Errorf("readCloser.ReadAll() error = %v, wantErr %v", err, tt.wantReadErr) - } - if !bytes.Equal(got, tt.wantData) { - t.Errorf("readCloser.ReadAll() = %v, want %v", got, tt.wantData) - } - if err := rc.Close(); err != tt.wantCloseErr { - t.Errorf("readCloser.Close() error = %v, wantErr %v", err, tt.wantCloseErr) - } - }) - } -} - type errorReader struct{} func (e *errorReader) Read(p []byte) (n int, err error) { From 31e5ada476b4b4f255422315a16853c0be88d809 Mon Sep 17 00:00:00 2001 From: "Lixia (Sylvia) Lei" Date: Fri, 6 Dec 2024 17:45:50 +0800 Subject: [PATCH 25/28] improve Signed-off-by: Lixia (Sylvia) Lei --- internal/trace/transport.go | 31 ++++++----- internal/trace/transport_test.go | 93 ++++++++++++++++++++++++++++++-- 2 files changed, 107 insertions(+), 17 deletions(-) diff --git a/internal/trace/transport.go b/internal/trace/transport.go index 540373dd0..86e3fefc7 100644 --- a/internal/trace/transport.go +++ b/internal/trace/transport.go @@ -38,7 +38,7 @@ var ( ) // payloadSizeLimit limits the maximum size of the response body to be printed. -const payloadSizeLimit int64 = 4 * 1024 // 4 KiB +const payloadSizeLimit int64 = 16 * 1024 // 16 KiB // Transport is an http.RoundTripper that keeps track of the in-flight // request and add hooks to report HTTP tracing events. @@ -66,9 +66,9 @@ func (t *Transport) RoundTrip(req *http.Request) (resp *http.Response, err error // log the response resp, err = t.RoundTripper.RoundTrip(req) if err != nil { - e.Errorf("Error in getting response: %w", err) + e.Errorf("<-- Response #%d\nError in getting response: %v", id, err) } else if resp == nil { - e.Errorf("No response obtained for request %s %q", req.Method, req.URL) + e.Errorf("<-- Response #%d\nNo response obtained for request %s %q", id, req.Method, req.URL) } else { e.Debugf("<-- Response #%d\n< Response Status: %q\n< Response headers:\n%s\n< Response body:\n%s", id, resp.Status, logHeader(resp.Header), logResponseBody(resp)) @@ -122,14 +122,17 @@ func logResponseBody(resp *http.Response) string { return fmt.Sprintf(" Error reading response body: %v", err) } - readBody := buf.Bytes() + readBody := buf.String() if len(readBody) == 0 { return " Response body is empty" } + if containsCredentials(readBody) { + return " Response body redacted due to potential credentials" + } if len(readBody) > int(payloadSizeLimit) { - return string(readBody[:payloadSizeLimit]) + "\n...(truncated)" + return readBody[:payloadSizeLimit] + "\n...(truncated)" } - return string(readBody) + return readBody } // isPrintableContentType returns true if the content of contentType is printable. @@ -139,13 +142,15 @@ func isPrintableContentType(contentType string) bool { return false } - if mediaType == "application/json" || strings.HasSuffix(mediaType, "+json") { - // JSON types - return true - } - if mediaType == "text/plain" { - // text types + switch mediaType { + case "application/json", // JSON types + "text/plain", "text/html": // text types return true } - return false + return strings.HasSuffix(mediaType, "+json") +} + +// containsCredentials returns true if the body contains potential credentials. +func containsCredentials(body string) bool { + return strings.Contains(body, `"token"`) || strings.Contains(body, `"access_token"`) } diff --git a/internal/trace/transport_test.go b/internal/trace/transport_test.go index 2b3376dd2..38b54520a 100644 --- a/internal/trace/transport_test.go +++ b/internal/trace/transport_test.go @@ -23,7 +23,13 @@ import ( "testing" ) -var mockReadErr = errors.New("mock read error") +var errMockRead = errors.New("mock read error") + +type errorReader struct{} + +func (e *errorReader) Read(p []byte) (n int, err error) { + return 0, errMockRead +} func Test_isPrintableContentType(t *testing.T) { tests := []struct { @@ -84,6 +90,16 @@ func Test_isPrintableContentType(t *testing.T) { { name: "HTML type", contentType: "text/html", + want: true, + }, + { + name: "Plain text type with charset", + contentType: "text/html; charset=utf-8", + want: true, + }, + { + name: "Random type with text/html prefix", + contentType: "text/htmlllll", want: false, }, { @@ -232,6 +248,24 @@ func Test_logResponseBody(t *testing.T) { }, want: "data", }, + { + name: "Body contains token", + resp: &http.Response{ + Body: io.NopCloser(bytes.NewReader([]byte(`{"token":"12345"}`))), + ContentLength: 17, + Header: http.Header{"Content-Type": []string{"application/json"}}, + }, + want: " Response body redacted due to potential credentials", + }, + { + name: "Body contains access_token", + resp: &http.Response{ + Body: io.NopCloser(bytes.NewReader([]byte(`{"access_token":"12345"}`))), + ContentLength: 17, + Header: http.Header{"Content-Type": []string{"application/json"}}, + }, + want: " Response body redacted due to potential credentials", + }, } for _, tt := range tests { @@ -285,8 +319,59 @@ func Test_logResponseBody_error(t *testing.T) { } } -type errorReader struct{} +func Test_containsCredentials(t *testing.T) { + tests := []struct { + name string + body string + want bool + }{ + { + name: "Contains token keyword", + body: `{"token": "12345"}`, + want: true, + }, + { + name: "Contains quoted token keyword", + body: `whatever "token" blah`, + want: true, + }, + { + name: "Contains unquoted token keyword", + body: `whatever token blah`, + want: false, + }, + { + name: "Contains access_token keyword", + body: `{"access_token": "12345"}`, + want: true, + }, + { + name: "Contains quoted access_token keyword", + body: `whatever "access_token" blah`, + want: true, + }, + { + name: "Contains unquoted access_token keyword", + body: `whatever access_token blah`, + want: false, + }, + { + name: "Does not contain credentials", + body: `{"key": "value"}`, + want: false, + }, + { + name: "Empty body", + body: ``, + want: false, + }, + } -func (e *errorReader) Read(p []byte) (n int, err error) { - return 0, mockReadErr + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + if got := containsCredentials(tt.body); got != tt.want { + t.Errorf("containsCredentials() = %v, want %v", got, tt.want) + } + }) + } } From aac4904eecda0fb94003a0da5f50c9d039c8d366 Mon Sep 17 00:00:00 2001 From: "Lixia (Sylvia) Lei" Date: Fri, 6 Dec 2024 17:49:22 +0800 Subject: [PATCH 26/28] fix ut Signed-off-by: Lixia (Sylvia) Lei --- internal/trace/transport_test.go | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/internal/trace/transport_test.go b/internal/trace/transport_test.go index 38b54520a..dd79c949a 100644 --- a/internal/trace/transport_test.go +++ b/internal/trace/transport_test.go @@ -255,7 +255,8 @@ func Test_logResponseBody(t *testing.T) { ContentLength: 17, Header: http.Header{"Content-Type": []string{"application/json"}}, }, - want: " Response body redacted due to potential credentials", + wantData: []byte(`{"token":"12345"}`), + want: " Response body redacted due to potential credentials", }, { name: "Body contains access_token", @@ -264,7 +265,8 @@ func Test_logResponseBody(t *testing.T) { ContentLength: 17, Header: http.Header{"Content-Type": []string{"application/json"}}, }, - want: " Response body redacted due to potential credentials", + wantData: []byte(`{"access_token":"12345"}`), + want: " Response body redacted due to potential credentials", }, } From b440250f05b5eb5bc88bf63920dcd4735be2e1e4 Mon Sep 17 00:00:00 2001 From: "Lixia (Sylvia) Lei" Date: Fri, 6 Dec 2024 18:23:58 +0800 Subject: [PATCH 27/28] minor fix Signed-off-by: Lixia (Sylvia) Lei --- internal/trace/transport.go | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/internal/trace/transport.go b/internal/trace/transport.go index 86e3fefc7..19e96a68c 100644 --- a/internal/trace/transport.go +++ b/internal/trace/transport.go @@ -104,7 +104,7 @@ func logResponseBody(resp *http.Response) string { // non-applicable body is not printed and remains untouched for subsequent processing contentType := resp.Header.Get("Content-Type") if !isPrintableContentType(contentType) { - return fmt.Sprintf(" Response body of content type \"%s\" is not printed", contentType) + return fmt.Sprintf(" Response body of content type %q is not printed", contentType) } buf := bytes.NewBuffer(nil) @@ -137,6 +137,10 @@ func logResponseBody(resp *http.Response) string { // isPrintableContentType returns true if the content of contentType is printable. func isPrintableContentType(contentType string) bool { + if len(contentType) == 0 { + return false + } + mediaType, _, err := mime.ParseMediaType(contentType) if err != nil { return false From cfc7169758a421f513cc1621f5a3febe1ea4a6be Mon Sep 17 00:00:00 2001 From: "Lixia (Sylvia) Lei" Date: Fri, 6 Dec 2024 18:37:19 +0800 Subject: [PATCH 28/28] handle empty content type Signed-off-by: Lixia (Sylvia) Lei --- internal/trace/transport.go | 7 +++---- internal/trace/transport_test.go | 19 +++++++++++++++++++ 2 files changed, 22 insertions(+), 4 deletions(-) diff --git a/internal/trace/transport.go b/internal/trace/transport.go index 19e96a68c..fa02f30d0 100644 --- a/internal/trace/transport.go +++ b/internal/trace/transport.go @@ -103,6 +103,9 @@ func logResponseBody(resp *http.Response) string { // non-applicable body is not printed and remains untouched for subsequent processing contentType := resp.Header.Get("Content-Type") + if contentType == "" { + return " Response body without a content type is not printed" + } if !isPrintableContentType(contentType) { return fmt.Sprintf(" Response body of content type %q is not printed", contentType) } @@ -137,10 +140,6 @@ func logResponseBody(resp *http.Response) string { // isPrintableContentType returns true if the content of contentType is printable. func isPrintableContentType(contentType string) bool { - if len(contentType) == 0 { - return false - } - mediaType, _, err := mime.ParseMediaType(contentType) if err != nil { return false diff --git a/internal/trace/transport_test.go b/internal/trace/transport_test.go index dd79c949a..764f216bf 100644 --- a/internal/trace/transport_test.go +++ b/internal/trace/transport_test.go @@ -178,6 +178,25 @@ func Test_logResponseBody(t *testing.T) { }, want: "whatever", }, + { + name: "Missing content type header", + wantData: []byte("whatever"), + resp: &http.Response{ + Body: io.NopCloser(bytes.NewReader([]byte("whatever"))), + ContentLength: 8, + }, + want: " Response body without a content type is not printed", + }, + { + name: "Empty content type header", + wantData: []byte("whatever"), + resp: &http.Response{ + Body: io.NopCloser(bytes.NewReader([]byte("whatever"))), + ContentLength: 8, + Header: http.Header{"Content-Type": []string{""}}, + }, + want: " Response body without a content type is not printed", + }, { name: "Non-printable content type", wantData: []byte("binary data"),