Revamp debug logs (#816)

* Revamp debug logs

1. Drop places that can log creds. May bring this back with build tags?
2. Introduce pkg/internal/redact to hold a context that signals we
should omit the body when dumping logs. Maybe this should live in
the logs package, but internal for now should be fine.
3. Stop logging the request and response body for blobs and token
responses.

* Apply redact ctx to request body

pkg/authn/keychain.go

@@ -15,12 +15,10 @@
 package authn
 
 import (
-	"encoding/json"
 	"os"
 
 	"github.com/docker/cli/cli/config"
 	"github.com/docker/cli/cli/config/types"
-	"github.com/google/go-containerregistry/pkg/logs"
 	"github.com/google/go-containerregistry/pkg/name"
 )
 
@@ -76,12 +74,6 @@ func (dk *defaultKeychain) Resolve(target Resource) (Authenticator, error) {
 	if err != nil {
 		return nil, err
 	}
-	if logs.Enabled(logs.Debug) {
-		b, err := json.Marshal(cfg)
-		if err == nil {
-			logs.Debug.Printf("defaultKeychain.Resolve(%q) = %s", key, string(b))
-		}
-	}
 
 	empty := types.AuthConfig{}
 	if cfg == empty {

pkg/authn/keychain_test.go

@@ -15,7 +15,6 @@
 package authn
 
 import (
-	"bytes"
 	"encoding/base64"
 	"fmt"
 	"io/ioutil"
@@ -24,7 +23,6 @@ import (
 	"reflect"
 	"testing"
 
-	"github.com/google/go-containerregistry/pkg/logs"
 	"github.com/google/go-containerregistry/pkg/name"
 )
 
@@ -114,22 +112,13 @@ func TestVariousPaths(t *testing.T) {
 		},
 	}}
 
-	var b bytes.Buffer
-	logs.Debug.SetOutput(&b)
-
 	for _, test := range tests {
 		cd := setupConfigFile(t, test.content)
 		// For some reason, these tempdirs don't get cleaned up.
 		defer os.RemoveAll(filepath.Dir(cd))
 
-		// Clear debug logs.
-		b.Reset()
-
 		auth, err := DefaultKeychain.Resolve(test.target)
 		if test.wantErr {
-			if b.Len() != 0 {
-				t.Errorf("didn't expect any logs, got: %v", b.String())
-			}
 			if err == nil {
 				t.Fatal("wanted err, got nil")
 			} else if err != nil {
@@ -148,8 +137,5 @@ func TestVariousPaths(t *testing.T) {
 		if !reflect.DeepEqual(cfg, test.cfg) {
 			t.Errorf("got %+v, want %+v", cfg, test.cfg)
 		}
-		if b.Len() == 0 {
-			t.Errorf("wanted logs, got nothing")
-		}
 	}
 }

pkg/internal/redact/redact.go

@@ -0,0 +1,35 @@
+// Copyright 2020 Google LLC All Rights Reserved.
+//
+// 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 redact contains a simple context signal for redacting requests.
+package redact
+
+import (
+	"context"
+)
+
+type contextKey string
+
+var redactKey = contextKey("redact")
+
+// NewContext creates a new ctx with the reason for redaction.
+func NewContext(ctx context.Context, reason string) context.Context {
+	return context.WithValue(ctx, redactKey, reason)
+}
+
+// FromContext returns the redaction reason, if any.
+func FromContext(ctx context.Context) (bool, string) {
+	reason, ok := ctx.Value(redactKey).(string)
+	return ok, reason
+}

pkg/v1/google/auth.go

@@ -120,13 +120,6 @@ func (tsa *tokenSourceAuth) Authorization() (*authn.AuthConfig, error) {
 		return nil, err
 	}
 
-	if logs.Enabled(logs.Debug) {
-		b, err := json.Marshal(token)
-		if err == nil {
-			logs.Debug.Printf("google.Keychain: %s", string(b))
-		}
-	}
-
 	return &authn.AuthConfig{
 		Username: "_token",
 		Password: token.AccessToken,

pkg/v1/remote/descriptor.go

@@ -348,14 +348,14 @@ func (f *fetcher) headManifest(ref name.Reference, acceptable []types.MediaType)
 	}, nil
 }
 
-func (f *fetcher) fetchBlob(h v1.Hash) (io.ReadCloser, error) {
+func (f *fetcher) fetchBlob(ctx context.Context, h v1.Hash) (io.ReadCloser, error) {
 	u := f.url("blobs", h.String())
 	req, err := http.NewRequest(http.MethodGet, u.String(), nil)
 	if err != nil {
 		return nil, err
 	}
 
-	resp, err := f.Client.Do(req.WithContext(f.context))
+	resp, err := f.Client.Do(req.WithContext(ctx))
 	if err != nil {
 		return nil, err
 	}

pkg/v1/remote/image.go

@@ -99,7 +99,7 @@ func (r *remoteImage) RawConfigFile() ([]byte, error) {
 		return nil, err
 	}
 
-	body, err := r.fetchBlob(m.Config.Digest)
+	body, err := r.fetchBlob(r.context, m.Config.Digest)
 	if err != nil {
 		return nil, err
 	}

pkg/v1/remote/layer.go

@@ -17,6 +17,7 @@ package remote
 import (
 	"io"
 
+	"github.com/google/go-containerregistry/pkg/internal/redact"
 	"github.com/google/go-containerregistry/pkg/name"
 	v1 "github.com/google/go-containerregistry/pkg/v1"
 	"github.com/google/go-containerregistry/pkg/v1/partial"
@@ -31,7 +32,9 @@ type remoteLayer struct {
 
 // Compressed implements partial.CompressedLayer
 func (rl *remoteLayer) Compressed() (io.ReadCloser, error) {
-	return rl.fetchBlob(rl.digest)
+	// We don't want to log binary layers -- this can break terminals.
+	ctx := redact.NewContext(rl.context, "omitting binary blobs from logs")
+	return rl.fetchBlob(ctx, rl.digest)
 }
 
 // Compressed implements partial.CompressedLayer

pkg/v1/remote/transport/bearer.go

@@ -24,6 +24,7 @@ import (
 	"strings"
 
 	"github.com/google/go-containerregistry/pkg/authn"
+	"github.com/google/go-containerregistry/pkg/internal/redact"
 	"github.com/google/go-containerregistry/pkg/name"
 )
 
@@ -212,7 +213,16 @@ func (bt *bearerTransport) refreshOauth() ([]byte, error) {
 	}
 
 	client := http.Client{Transport: bt.inner}
-	resp, err := client.PostForm(u.String(), v)
+	req, err := http.NewRequest(http.MethodPost, u.String(), strings.NewReader(v.Encode()))
+	if err != nil {
+		return nil, err
+	}
+	req.Header.Set("Content-Type", "application/x-www-form-urlencoded")
+
+	// We don't want to log credentials.
+	ctx := redact.NewContext(req.Context(), "oauth token response contains credentials")
+
+	resp, err := client.Do(req.WithContext(ctx))
 	if err != nil {
 		return nil, err
 	}
@@ -243,7 +253,15 @@ func (bt *bearerTransport) refreshBasic() ([]byte, error) {
 	v.Set("service", bt.service)
 	u.RawQuery = v.Encode()
 
-	resp, err := client.Get(u.String())
+	req, err := http.NewRequest(http.MethodGet, u.String(), nil)
+	if err != nil {
+		return nil, err
+	}
+
+	// We don't want to log credentials.
+	ctx := redact.NewContext(req.Context(), "basic token response contains credentials")
+
+	resp, err := client.Do(req.WithContext(ctx))
 	if err != nil {
 		return nil, err
 	}

pkg/v1/remote/transport/error.go

@@ -59,7 +59,7 @@ var _ error = (*Error)(nil)
 func (e *Error) Error() string {
 	prefix := ""
 	if e.request != nil {
-		prefix = fmt.Sprintf("%s %s: ", e.request.Method, redact(e.request.URL))
+		prefix = fmt.Sprintf("%s %s: ", e.request.Method, redactURL(e.request.URL))
 	}
 	return prefix + e.responseErr()
 }
@@ -96,7 +96,8 @@ func (e *Error) Temporary() bool {
 	return true
 }
 
-func redact(original *url.URL) *url.URL {
+// TODO(jonjohnsonjr): Consider moving to pkg/internal/redact.
+func redactURL(original *url.URL) *url.URL {
 	qs := original.Query()
 	for k, v := range qs {
 		for i := range v {

pkg/v1/remote/transport/logger.go

@@ -1,10 +1,26 @@
+// Copyright 2020 Google LLC All Rights Reserved.
+//
+// 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 transport
 
 import (
 	"fmt"
 	"net/http"
 	"net/http/httputil"
+	"time"
 
+	"github.com/google/go-containerregistry/pkg/internal/redact"
 	"github.com/google/go-containerregistry/pkg/logs"
 )
 
@@ -20,24 +36,56 @@ func NewLogger(inner http.RoundTripper) http.RoundTripper {
 
 func (t *logTransport) RoundTrip(in *http.Request) (out *http.Response, err error) {
 	// Inspired by: github.com/motemen/go-loghttp
-	logs.Debug.Printf("--> %s %s", in.Method, in.URL)
-	b, err := httputil.DumpRequestOut(in, true)
+	msg := fmt.Sprintf("--> %s %s", in.Method, in.URL)
+
+	// We redact token responses and binary blobs in response/request.
+	omitBody, reason := redact.FromContext(in.Context())
+	if omitBody {
+		msg = fmt.Sprintf("%s [body redacted: %s]", msg, reason)
+	}
+
+	logs.Debug.Printf(msg)
+
+	// Save these headers so we can redact Authorization.
+	savedHeaders := in.Header.Clone()
+	if in.Header != nil {
+		in.Header.Set("authorization", "<redacted>")
+	}
+
+	b, err := httputil.DumpRequestOut(in, !omitBody)
 	if err == nil {
 		logs.Debug.Println(string(b))
+	} else {
+		logs.Debug.Printf("Failed to dump request %s %s: %v", in.Method, in.URL, err)
 	}
+
+	// Restore the non-redacted headers.
+	in.Header = savedHeaders
+
+	start := time.Now()
 	out, err = t.inner.RoundTrip(in)
+	duration := time.Since(start)
 	if err != nil {
-		logs.Debug.Printf("<-- %v %s", err, in.URL)
+		logs.Debug.Printf("<-- %v %s %s (%s)", err, in.Method, in.URL, duration)
 	}
 	if out != nil {
 		msg := fmt.Sprintf("<-- %d", out.StatusCode)
 		if out.Request != nil {
 			msg = fmt.Sprintf("%s %s", msg, out.Request.URL)
 		}
+		msg = fmt.Sprintf("%s (%s)", msg, duration)
+
+		if omitBody {
+			msg = fmt.Sprintf("%s [body redacted: %s]", msg, reason)
+		}
+
 		logs.Debug.Print(msg)
-		b, err := httputil.DumpResponse(out, true)
+
+		b, err := httputil.DumpResponse(out, !omitBody)
 		if err == nil {
 			logs.Debug.Println(string(b))
+		} else {
+			logs.Debug.Printf("Failed to dump response %s %s: %v", in.Method, in.URL, err)
 		}
 	}
 	return

pkg/v1/remote/transport/logger_test.go

@@ -16,29 +16,41 @@ package transport
 
 import (
 	"bytes"
+	"context"
 	"errors"
 	"io/ioutil"
 	"net/http"
 	"strings"
 	"testing"
 
+	"github.com/google/go-containerregistry/pkg/internal/redact"
 	"github.com/google/go-containerregistry/pkg/logs"
 )
 
 func TestLogger(t *testing.T) {
 	canary := "logs.Debug canary"
-	req, err := http.NewRequest("GET", "http://example.com", nil)
+	secret := "super secret do not log"
+	auth := "my token pls do not log"
+	reason := "should not log the secret"
+
+	ctx := redact.NewContext(context.Background(), reason)
+
+	req, err := http.NewRequestWithContext(ctx, "GET", "http://example.com", nil)
 	if err != nil {
 		t.Fatalf("Unexpected error during NewRequest: %v", err)
 	}
+	req.Header.Set("authorization", auth)
 
 	var b bytes.Buffer
 	logs.Debug.SetOutput(&b)
 	cannedResponse := http.Response{
 		Status:     http.StatusText(http.StatusOK),
 		StatusCode: http.StatusOK,
-		Body:       ioutil.NopCloser(strings.NewReader(canary)),
-		Request:    req,
+		Header: http.Header{
+			"Foo": []string{canary},
+		},
+		Body:    ioutil.NopCloser(strings.NewReader(secret)),
+		Request: req,
 	}
 	tr := NewLogger(newRecorder(&cannedResponse, nil))
 	if _, err := tr.RoundTrip(req); err != nil {
@@ -49,6 +61,15 @@ func TestLogger(t *testing.T) {
 	if !strings.Contains(logged, canary) {
 		t.Errorf("Expected logs to contain %s, got %s", canary, logged)
 	}
+	if !strings.Contains(logged, reason) {
+		t.Errorf("Expected logs to contain %s, got %s", canary, logged)
+	}
+	if strings.Contains(logged, secret) {
+		t.Errorf("Expected logs NOT to contain %s, got %s", secret, logged)
+	}
+	if strings.Contains(logged, auth) {
+		t.Errorf("Expected logs NOT to contain %s, got %s", auth, logged)
+	}
 }
 
 func TestLoggerError(t *testing.T) {