fix(logging): credentials in headers are leaked via log

Refs: #77

Author: Links2004

pkg/configuration/new_fetcher.go

@@ -28,9 +28,11 @@ func NewFetcherFromConfiguration(configuration *pb.FetcherConfiguration,
 	authorizer auth.Authorizer,
 ) (fetch.Fetcher, error) {
 	var fetcher fetch.Fetcher
+	var loggedHeaderNames []string
 	if configuration == nil {
 		fetcher = fetch.DefaultFetcher
 	} else {
+		loggedHeaderNames = configuration.LoggedHeaderNames
 		switch backend := configuration.Backend.(type) {
 		case *pb.FetcherConfiguration_Http:
 			roundTripper, err := bb_http.NewRoundTripperFromConfiguration(backend.Http.Client)
@@ -62,6 +64,7 @@ func NewFetcherFromConfiguration(configuration *pb.FetcherConfiguration,
 		fetch.NewMetricsFetcher(
 			fetch.NewLoggingFetcher(
 				fetch.NewValidatingFetcher(fetcher),
+				loggedHeaderNames,
 			),
 			clock.SystemClock,
 			"fetch",

pkg/fetch/BUILD.bazel

@@ -70,3 +70,13 @@ go_test(
         "@org_golang_google_protobuf//types/known/timestamppb",
     ],
 )
+
+go_test(
+    name = "logging_fetcher_internal_test",
+    srcs = ["logging_fetcher_test.go"],
+    embed = [":fetch"],
+    deps = [
+        "@bazel_remote_apis//build/bazel/remote/asset/v1:remote_asset_go_proto",
+        "@com_github_stretchr_testify//require",
+    ],
+)

pkg/fetch/http_fetcher.go

@@ -5,6 +5,7 @@ import (
 	"encoding/base64"
 	"encoding/hex"
 	"errors"
+	"fmt"
 	"io"
 	"log"
 	"net/http"
@@ -270,21 +271,29 @@ func getAuthHeaders(uris []string, qualifiers []*remoteasset.Qualifier) (*AuthHe
 	}
 	// If we have per URL headers, we need to go through and apply them after applying the global headers.
 	for k, v := range perURLQualifiers {
-		parts := strings.Split(k, ":")
-		if len(parts) != 3 {
-			return nil, status.Errorf(codes.InvalidArgument, "Invalid http_header_url qualifier: %s", k)
-		}
-		uriIdx, err := strconv.ParseInt(parts[1], 10, 64)
+		uriIdx, header, err := parseHTTPHeaderURLQualifierName(k)
 		if err != nil {
-			return nil, status.Errorf(codes.InvalidArgument, "Invalid http_header_url qualifier: %s: Bad URL index: %v: %v", k, parts[1], err)
+			return nil, status.Errorf(codes.InvalidArgument, "%s", err.Error())
 		}
-		if uriIdx < 0 || uriIdx >= int64(len(uris)) {
+		if uriIdx < 0 || uriIdx >= len(uris) {
 			return nil, status.Errorf(codes.InvalidArgument, "Invalid http_header_url qualifier: %s: URL index out of range: %v", k, uriIdx)
 		}
-		header := parts[2]
 		ah.AddHeader(uris[uriIdx], header, v)
-
 	}
 
 	return &ah, nil
 }
+
+// parseHTTPHeaderURLQualifierName parses the URI index and header name
+// encoded in a "http_header_url:<index>:<header>" qualifier name.
+func parseHTTPHeaderURLQualifierName(name string) (int, string, error) {
+	parts := strings.SplitN(name, ":", 3)
+	if len(parts) != 3 {
+		return 0, "", fmt.Errorf("invalid http_header_url qualifier: %s", name)
+	}
+	uriIdx, err := strconv.ParseInt(parts[1], 10, 64)
+	if err != nil {
+		return 0, "", fmt.Errorf("invalid http_header_url qualifier: %s: bad URL index: %v: %w", name, parts[1], err)
+	}
+	return int(uriIdx), parts[2], nil
+}

pkg/fetch/logging_fetcher.go

@@ -2,26 +2,40 @@ package fetch
 
 import (
 	"context"
+	"encoding/json"
+	"fmt"
 	"log"
+	"strings"
 
 	remoteasset "github.com/bazelbuild/remote-apis/build/bazel/remote/asset/v1"
 	"github.com/buildbarn/bb-remote-asset/pkg/qualifier"
 	"google.golang.org/grpc/status"
 )
 
+const redactedValue = "<redacted>"
+
 type loggingFetcher struct {
-	fetcher Fetcher
+	fetcher           Fetcher
+	loggedHeaderNames map[string]struct{}
 }
 
-// NewLoggingFetcher creates a fetcher which logs requests and results
-func NewLoggingFetcher(fetcher Fetcher) Fetcher {
+// NewLoggingFetcher creates a fetcher which logs requests and results.
+//
+// Qualifier values that carry HTTP header contents which may contain secrets such as "Authorization" tokens.
+// Their values are redacted from the log unless the corresponding header name is present in loggedHeaderNames.
+func NewLoggingFetcher(fetcher Fetcher, loggedHeaderNames []string) Fetcher {
+	names := make(map[string]struct{}, len(loggedHeaderNames))
+	for _, name := range loggedHeaderNames {
+		names[strings.ToLower(name)] = struct{}{}
+	}
 	return &loggingFetcher{
-		fetcher: fetcher,
+		fetcher:           fetcher,
+		loggedHeaderNames: names,
 	}
 }
 
 func (lf *loggingFetcher) FetchBlob(ctx context.Context, req *remoteasset.FetchBlobRequest) (*remoteasset.FetchBlobResponse, error) {
-	log.Printf("Fetching Blob %s with qualifiers %s", req.Uris, req.Qualifiers)
+	log.Printf("Fetching Blob %s with qualifiers %s", req.Uris, lf.redactQualifiers(req.Qualifiers))
 	resp, err := lf.fetcher.FetchBlob(ctx, req)
 	if err == nil {
 		log.Printf("FetchBlob completed for %s with status code %d", req.Uris, resp.Status.GetCode())
@@ -32,7 +46,7 @@ func (lf *loggingFetcher) FetchBlob(ctx context.Context, req *remoteasset.FetchB
 }
 
 func (lf *loggingFetcher) FetchDirectory(ctx context.Context, req *remoteasset.FetchDirectoryRequest) (*remoteasset.FetchDirectoryResponse, error) {
-	log.Printf("Fetching Directory %s with qualifiers %s", req.Uris, req.Qualifiers)
+	log.Printf("Fetching Directory %s with qualifiers %s", req.Uris, lf.redactQualifiers(req.Qualifiers))
 	resp, err := lf.fetcher.FetchDirectory(ctx, req)
 	if err == nil {
 		log.Printf("FetchBlob completed for %s with status code %d", req.Uris, resp.Status.GetCode())
@@ -45,3 +59,63 @@ func (lf *loggingFetcher) FetchDirectory(ctx context.Context, req *remoteasset.F
 func (lf *loggingFetcher) CheckQualifiers(qualifiers qualifier.Set) qualifier.Set {
 	return lf.fetcher.CheckQualifiers(qualifiers)
 }
+
+func (lf *loggingFetcher) isHeaderNameLogged(headerName string) bool {
+	_, ok := lf.loggedHeaderNames[strings.ToLower(headerName)]
+	return ok
+}
+
+// redactQualifiers formats qualifiers for logging,
+// redacting the values of any HTTP header qualifiers whose header name isn't whitelisted.
+func (lf *loggingFetcher) redactQualifiers(qualifiers []*remoteasset.Qualifier) string {
+	parts := make([]string, 0, len(qualifiers))
+	for _, q := range qualifiers {
+		parts = append(parts, fmt.Sprintf("name:%q value:%q", q.Name, lf.redactQualifierValue(q)))
+	}
+	return "[" + strings.Join(parts, " ") + "]"
+}
+
+func (lf *loggingFetcher) redactQualifierValue(q *remoteasset.Qualifier) string {
+	switch {
+	case q.Name == QualifierLegacyBazelHTTPHeaders:
+		return lf.redactLegacyAuthHeaders(q.Value)
+	case strings.HasPrefix(q.Name, QualifierHTTPHeaderURLPrefix):
+		_, header, err := parseHTTPHeaderURLQualifierName(q.Name)
+		if err != nil || !lf.isHeaderNameLogged(header) {
+			return redactedValue
+		}
+		return q.Value
+	case strings.HasPrefix(q.Name, QualifierHTTPHeaderPrefix):
+		header := strings.TrimPrefix(q.Name, QualifierHTTPHeaderPrefix)
+		if !lf.isHeaderNameLogged(header) {
+			return redactedValue
+		}
+		return q.Value
+	default:
+		return q.Value
+	}
+}
+
+// redactLegacyAuthHeaders redacts the header values carried by a legacy
+// "bazel.auth_headers" qualifier, keeping only whitelisted header names.
+func (lf *loggingFetcher) redactLegacyAuthHeaders(value string) string {
+	ah, err := NewAuthHeadersFromQualifier(value)
+	if err != nil {
+		return redactedValue
+	}
+	redacted := NewAuthHeaders()
+	for uri, headers := range *ah {
+		for header, v := range headers {
+			if lf.isHeaderNameLogged(header) {
+				redacted.AddHeader(uri, header, v)
+			} else {
+				redacted.AddHeader(uri, header, redactedValue)
+			}
+		}
+	}
+	b, err := json.Marshal(redacted)
+	if err != nil {
+		return redactedValue
+	}
+	return string(b)
+}

pkg/fetch/logging_fetcher_test.go

@@ -0,0 +1,114 @@
+package fetch
+
+import (
+	"testing"
+
+	remoteasset "github.com/bazelbuild/remote-apis/build/bazel/remote/asset/v1"
+	"github.com/stretchr/testify/require"
+)
+
+func newTestLoggingFetcher(loggedHeaderNames []string) *loggingFetcher {
+	lf := NewLoggingFetcher(nil, loggedHeaderNames)
+	return lf.(*loggingFetcher)
+}
+
+func TestIsHeaderNameLogged(t *testing.T) {
+	lf := newTestLoggingFetcher([]string{"Authorization", "X-Custom"})
+
+	require.True(t, lf.isHeaderNameLogged("Authorization"))
+	require.True(t, lf.isHeaderNameLogged("authorization"))
+	require.True(t, lf.isHeaderNameLogged("X-Custom"))
+	require.False(t, lf.isHeaderNameLogged("X-Other"))
+}
+
+func TestRedactQualifierValue(t *testing.T) {
+	lf := newTestLoggingFetcher([]string{"X-Custom"})
+
+	tests := []struct {
+		name string
+		q    *remoteasset.Qualifier
+		want string
+	}{
+		{
+			name: "http_header allowed",
+			q:    &remoteasset.Qualifier{Name: "http_header:X-Custom", Value: "visible-value"},
+			want: "visible-value",
+		},
+		{
+			name: "http_header not allowed",
+			q:    &remoteasset.Qualifier{Name: "http_header:Authorization", Value: "Bearer secret-token"},
+			want: redactedValue,
+		},
+		{
+			name: "http_header_url allowed",
+			q:    &remoteasset.Qualifier{Name: "http_header_url:0:X-Custom", Value: "visible-value"},
+			want: "visible-value",
+		},
+		{
+			name: "http_header_url not allowed",
+			q:    &remoteasset.Qualifier{Name: "http_header_url:0:Authorization", Value: "Bearer secret-token"},
+			want: redactedValue,
+		},
+		{
+			name: "http_header_url malformed",
+			q:    &remoteasset.Qualifier{Name: "http_header_url:not-an-index:X-Custom", Value: "visible-value"},
+			want: redactedValue,
+		},
+		{
+			name: "legacy auth headers",
+			q:    &remoteasset.Qualifier{Name: QualifierLegacyBazelHTTPHeaders, Value: `{"source.test":{"X-Custom":"visible-value"}}`},
+			want: `{"source.test":{"X-Custom":"visible-value"}}`,
+		},
+		{
+			name: "legacy auth headers malformed",
+			q:    &remoteasset.Qualifier{Name: QualifierLegacyBazelHTTPHeaders, Value: "not-json"},
+			want: redactedValue,
+		},
+		{
+			name: "other qualifier passthrough",
+			q:    &remoteasset.Qualifier{Name: "checksum.sri", Value: "sha256-abc123"},
+			want: "sha256-abc123",
+		},
+	}
+
+	for _, tc := range tests {
+		t.Run(tc.name, func(t *testing.T) {
+			require.Equal(t, tc.want, lf.redactQualifierValue(tc.q))
+		})
+	}
+}
+
+func TestRedactLegacyAuthHeaders(t *testing.T) {
+	lf := newTestLoggingFetcher([]string{"X-Custom"})
+
+	t.Run("mixed allowed and redacted headers", func(t *testing.T) {
+		got := lf.redactLegacyAuthHeaders(`{"source.test":{"Authorization":"Bearer secret-token","X-Custom":"visible-value"}}`)
+		require.NotContains(t, got, "secret-token")
+		require.Contains(t, got, "visible-value")
+
+		ah, err := NewAuthHeadersFromQualifier(got)
+		require.NoError(t, err)
+		require.Equal(t, redactedValue, (*ah)["source.test"]["Authorization"])
+		require.Equal(t, "visible-value", (*ah)["source.test"]["X-Custom"])
+	})
+
+	t.Run("malformed JSON", func(t *testing.T) {
+		require.Equal(t, redactedValue, lf.redactLegacyAuthHeaders("not-json"))
+	})
+}
+
+func TestRedactQualifiers(t *testing.T) {
+	lf := newTestLoggingFetcher([]string{"X-Custom"})
+
+	qualifiers := []*remoteasset.Qualifier{
+		{Name: "http_header:X-Custom", Value: "visible-value"},
+		{Name: "http_header:Authorization", Value: "Bearer secret-token"},
+		{Name: "checksum.sri", Value: "sha256-abc123"},
+	}
+
+	got := lf.redactQualifiers(qualifiers)
+	require.NotContains(t, got, "secret-token")
+	require.Contains(t, got, `name:"http_header:X-Custom" value:"visible-value"`)
+	require.Contains(t, got, `name:"http_header:Authorization" value:"<redacted>"`)
+	require.Contains(t, got, `name:"checksum.sri" value:"sha256-abc123"`)
+}

pkg/proto/configuration/bb_remote_asset/fetch/fetcher.pb.go

@@ -38,6 +38,16 @@ message FetcherConfiguration {
     RemoteExecutionFetcherConfiguration remote_execution = 4;
   }
 
+  // Optional: Names of HTTP headers (case-insensitive) whose values
+  // are permitted to be written to the log.
+  //
+  // Qualifiers such as "http_header:<name>", "http_header_url:<idx>:<name>"
+  // and the legacy "bazel.auth_headers" may carry sensitive
+  // values (e.g. "Authorization" tokens).
+  // By default, the values of all such headers are redacted from the log.
+  // Add a header name to this list to permit its value to be logged.
+  repeated string logged_header_names = 5;
+
   message HttpFetcherConfiguration {
     // Formerly used to specify CAS
     reserved 1;