From 5fe7a87138a3fb4903575fb20b5bb9b98c87a56b Mon Sep 17 00:00:00 2001 From: Terry Howe Date: Mon, 26 May 2025 11:48:24 -0600 Subject: [PATCH] fix: add debug logging to oci transport Signed-off-by: Terry Howe Co-authored-by: Billy Zha --- pkg/registry/client.go | 26 +-- pkg/registry/transport.go | 175 +++++++++++++++ pkg/registry/transport_test.go | 399 +++++++++++++++++++++++++++++++++ 3 files changed, 580 insertions(+), 20 deletions(-) create mode 100644 pkg/registry/transport.go create mode 100644 pkg/registry/transport_test.go diff --git a/pkg/registry/client.go b/pkg/registry/client.go index c5ab0b4ba..b8235927b 100644 --- a/pkg/registry/client.go +++ b/pkg/registry/client.go @@ -100,27 +100,8 @@ func NewClient(options ...ClientOption) (*Client, error) { client.credentialsFile = helmpath.ConfigPath(CredentialsFileBasename) } if client.httpClient == nil { - type cloner[T any] interface { - Clone() T - } - - // try to copy (clone) the http.DefaultTransport so any mutations we - // perform on it (e.g. TLS config) are not reflected globally - // follow https://github.com/golang/go/issues/39299 for a more elegant - // solution in the future - transport := http.DefaultTransport - if t, ok := transport.(cloner[*http.Transport]); ok { - transport = t.Clone() - } else if t, ok := transport.(cloner[http.RoundTripper]); ok { - // this branch will not be used with go 1.20, it was added - // optimistically to try to clone if the http.DefaultTransport - // implementation changes, still the Clone method in that case - // might not return http.RoundTripper... - transport = t.Clone() - } - client.httpClient = &http.Client{ - Transport: retry.NewTransport(transport), + Transport: NewTransport(client.debug), } } @@ -296,6 +277,11 @@ func ensureTLSConfig(client *auth.Client) (*tls.Config, error) { switch t := t.Base.(type) { case *http.Transport: transport = t + case *LoggingTransport: + switch t := t.RoundTripper.(type) { + case *http.Transport: + transport = t + } } } diff --git a/pkg/registry/transport.go b/pkg/registry/transport.go new file mode 100644 index 000000000..7b9c6744b --- /dev/null +++ b/pkg/registry/transport.go @@ -0,0 +1,175 @@ +/* +Copyright The Helm 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 registry + +import ( + "bytes" + "fmt" + "io" + "log/slog" + "mime" + "net/http" + "strings" + "sync/atomic" + + "oras.land/oras-go/v2/registry/remote/retry" +) + +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", + } +) + +// payloadSizeLimit limits the maximum size of the response body to be printed. +const payloadSizeLimit int64 = 16 * 1024 // 16 KiB + +// LoggingTransport is an http.RoundTripper that keeps track of the in-flight +// request and add hooks to report HTTP tracing events. +type LoggingTransport struct { + http.RoundTripper +} + +// NewTransport creates and returns a new instance of LoggingTransport +func NewTransport(debug bool) *retry.Transport { + type cloner[T any] interface { + Clone() T + } + + // try to copy (clone) the http.DefaultTransport so any mutations we + // perform on it (e.g. TLS config) are not reflected globally + // follow https://github.com/golang/go/issues/39299 for a more elegant + // solution in the future + transport := http.DefaultTransport + if t, ok := transport.(cloner[*http.Transport]); ok { + transport = t.Clone() + } else if t, ok := transport.(cloner[http.RoundTripper]); ok { + // this branch will not be used with go 1.20, it was added + // optimistically to try to clone if the http.DefaultTransport + // implementation changes, still the Clone method in that case + // might not return http.RoundTripper... + transport = t.Clone() + } + if debug { + transport = &LoggingTransport{RoundTripper: transport} + } + + return retry.NewTransport(transport) +} + +// RoundTrip calls base round trip while keeping track of the current request. +func (t *LoggingTransport) RoundTrip(req *http.Request) (resp *http.Response, err error) { + id := atomic.AddUint64(&requestCount, 1) - 1 + + slog.Debug("Request", "id", id, "url", req.URL, "method", req.Method, "header", logHeader(req.Header)) + resp, err = t.RoundTripper.RoundTrip(req) + if err != nil { + slog.Debug("Response", "id", id, "error", err) + } else if resp != nil { + slog.Debug("Response", "id", id, "status", resp.Status, "header", logHeader(resp.Header), "body", logResponseBody(resp)) + } else { + slog.Debug("Response", "id", id, "response", "nil") + } + + return resp, err +} + +// logHeader prints out the provided header keys and values, with auth header scrubbed. +func logHeader(header http.Header) string { + if len(header) > 0 { + headers := []string{} + for k, v := range header { + for _, h := range toScrub { + if strings.EqualFold(k, h) { + v = []string{"*****"} + } + } + headers = append(headers, fmt.Sprintf(" %q: %q", k, strings.Join(v, ", "))) + } + return strings.Join(headers, "\n") + } + return " Empty header" +} + +// logResponseBody prints out the response body if it is printable and within size limit. +func logResponseBody(resp *http.Response) string { + if resp.Body == nil || resp.Body == http.NoBody { + 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 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) + } + + 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 + if _, err := io.CopyN(buf, body, payloadSizeLimit+1); err != nil && err != io.EOF { + return fmt.Sprintf(" Error reading response body: %v", err) + } + + 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 readBody[:payloadSizeLimit] + "\n...(truncated)" + } + return readBody +} + +// isPrintableContentType returns true if the contentType is printable. +func isPrintableContentType(contentType string) bool { + mediaType, _, err := mime.ParseMediaType(contentType) + if err != nil { + return false + } + + switch mediaType { + case "application/json", // JSON types + "text/plain", "text/html": // text types + return true + } + 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/pkg/registry/transport_test.go b/pkg/registry/transport_test.go new file mode 100644 index 000000000..b4990c526 --- /dev/null +++ b/pkg/registry/transport_test.go @@ -0,0 +1,399 @@ +/* +Copyright The Helm 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 registry + +import ( + "bytes" + "errors" + "io" + "net/http" + "testing" +) + +var errMockRead = errors.New("mock read error") + +type errorReader struct{} + +func (e *errorReader) Read(_ []byte) (n int, err error) { + return 0, errMockRead +} + +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: "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", + 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: "Random type with text/plain prefix", + contentType: "text/plainnnnn", + want: false, + }, + { + 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, + }, + { + name: "Binary type", + contentType: "application/octet-stream", + want: false, + }, + { + name: "Unknown type", + contentType: "unknown/unknown", + want: false, + }, + { + name: "Invalid type", + contentType: "text/", + want: false, + }, + { + name: "Random string", + contentType: "random123!@#", + 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 + wantData []byte + }{ + { + name: "Nil body", + resp: &http.Response{ + Body: nil, + Header: http.Header{"Content-Type": []string{"application/json"}}, + }, + want: " No response body to print", + }, + { + 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 + Header: http.Header{"Content-Type": []string{"application/json"}}, + }, + want: " No response body to print", + }, + { + name: "Empty body", + wantData: []byte(""), + resp: &http.Response{ + Body: io.NopCloser(bytes.NewReader([]byte(""))), + ContentLength: 0, + Header: http.Header{"Content-Type": []string{"text/plain"}}, + }, + want: " Response body is empty", + }, + { + name: "Unknown content length", + wantData: []byte("whatever"), + resp: &http.Response{ + Body: io.NopCloser(bytes.NewReader([]byte("whatever"))), + ContentLength: -1, + Header: http.Header{"Content-Type": []string{"text/plain"}}, + }, + 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"), + resp: &http.Response{ + 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", + wantData: bytes.Repeat([]byte("a"), int(payloadSizeLimit)), + resp: &http.Response{ + Body: io.NopCloser(bytes.NewReader(bytes.Repeat([]byte("a"), int(payloadSizeLimit)))), + ContentLength: payloadSizeLimit, + Header: http.Header{"Content-Type": []string{"text/plain"}}, + }, + want: string(bytes.Repeat([]byte("a"), int(payloadSizeLimit))), + }, + { + 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, + Header: http.Header{"Content-Type": []string{"text/plain"}}, + }, + want: string(bytes.Repeat([]byte("a"), int(payloadSizeLimit))) + "\n...(truncated)", + }, + { + name: "Printable content type within limit", + wantData: []byte("data"), + resp: &http.Response{ + Body: io.NopCloser(bytes.NewReader([]byte("data"))), + ContentLength: 4, + Header: http.Header{"Content-Type": []string{"text/plain"}}, + }, + want: "data", + }, + { + 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 + Header: http.Header{"Content-Type": []string{"text/plain"}}, + }, + want: "data", + }, + { + 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 + Header: http.Header{"Content-Type": []string{"text/plain"}}, + }, + want: string(bytes.Repeat([]byte("a"), int(payloadSizeLimit))) + "\n...(truncated)", + }, + { + 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 + Header: http.Header{"Content-Type": []string{"text/plain"}}, + }, + 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"}}, + }, + wantData: []byte(`{"token":"12345"}`), + 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"}}, + }, + wantData: []byte(`{"access_token":"12345"}`), + want: " Response body redacted due to potential credentials", + }, + } + + 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{ + Body: io.NopCloser(&errorReader{}), + ContentLength: 10, + Header: http.Header{"Content-Type": []string{"text/plain"}}, + }, + want: " Error reading response body: mock read 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) + } + if closeErr := tt.resp.Body.Close(); closeErr != nil { + t.Errorf("failed to close body after logResponseBody(), err= %v", closeErr) + } + }) + } +} + +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, + }, + } + + 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) + } + }) + } +}