Redact http header values in logs

auth/opa/rpcauth/rpcauth.go

@@ -20,14 +20,20 @@ package rpcauth
 
 import (
 	"context"
+	"encoding/json"
+	"fmt"
 	"strings"
 
 	"github.com/go-logr/logr"
 	"go.opentelemetry.io/otel/attribute"
 	"google.golang.org/grpc"
 	"google.golang.org/grpc/codes"
 	"google.golang.org/grpc/status"
+	"google.golang.org/protobuf/encoding/protojson"
 	"google.golang.org/protobuf/proto"
+	"google.golang.org/protobuf/reflect/protoreflect"
+	"google.golang.org/protobuf/reflect/protoregistry"
+	"google.golang.org/protobuf/types/descriptorpb"
 
 	"github.com/Snowflake-Labs/sansshell/auth/opa"
 	"github.com/Snowflake-Labs/sansshell/telemetry/metrics"
@@ -88,6 +94,110 @@ func NewWithPolicy(ctx context.Context, policy string, authzHooks ...RPCAuthzHoo
 	return New(p, authzHooks...), nil
 }
 
+func isMessage(descriptor protoreflect.FieldDescriptor) bool {
+	return descriptor.Kind() == protoreflect.MessageKind || descriptor.Kind() == protoreflect.GroupKind
+}
+
+func isDebugRedactEnabled(fd protoreflect.FieldDescriptor) bool {
+	opts, ok := fd.Options().(*descriptorpb.FieldOptions)
+	if !ok {
+		return false
+	}
+	return opts.GetDebugRedact()
+}
+
+func redactListField(value protoreflect.Value) {
+	for i := 0; i < value.List().Len(); i++ {
+		redactFields(value.List().Get(i).Message())
+	}
+}
+
+func redactMapField(value protoreflect.Value) {
+	value.Map().Range(func(mapKey protoreflect.MapKey, mapValue protoreflect.Value) bool {
+		redactFields(mapValue.Message())
+		return true
+	})
+}
+
+func redactNestedMessage(message protoreflect.Message, descriptor protoreflect.FieldDescriptor, value protoreflect.Value) {
+	switch {
+	case descriptor.IsList() && isMessage(descriptor):
+		redactListField(value)
+	case descriptor.IsMap() && isMessage(descriptor):
+		redactMapField(value)
+	case !descriptor.IsMap() && isMessage(descriptor):
+		redactFields(value.Message())
+	}
+}
+
+func redactSingleField(message protoreflect.Message, descriptor protoreflect.FieldDescriptor) {
+	if descriptor.Kind() == protoreflect.StringKind {
+		if descriptor.Cardinality() != protoreflect.Repeated {
+			message.Set(descriptor, protoreflect.ValueOfString("--REDACTED--"))
+		} else {
+			list := message.Mutable(descriptor).List()
+			for i := 0; i < list.Len(); i++ {
+				list.Set(i, protoreflect.ValueOfString("--REDACTED--"))
+			}
+		}
+	} else {
+		// other than string, clear it
+		message.Clear(descriptor)
+	}
+}
+
+func redactFields(message protoreflect.Message) {
+	message.Range(
+		func(descriptor protoreflect.FieldDescriptor, value protoreflect.Value) bool {
+			if isDebugRedactEnabled(descriptor) {
+				redactSingleField(message, descriptor)
+				return true
+			}
+			redactNestedMessage(message, descriptor, value)
+			return true
+		},
+	)
+}
+
+const mockMessageType = "Mock.MockRequest"
+
+func getRedactedInput(input *RPCAuthInput) (RPCAuthInput, error) {
+	if input == nil {
+		return RPCAuthInput{}, nil
+	}
+	redactedInput := RPCAuthInput{
+		Method:      input.Method,
+		MessageType: input.MessageType,
+		Metadata:    input.Metadata,
+		Peer:        input.Peer,
+		Host:        input.Host,
+		Environment: input.Environment,
+		Extensions:  input.Extensions,
+	}
+	if input.MessageType == mockMessageType || input.MessageType == "" {
+		return redactedInput, nil
+	}
+	var redactedMessage protoreflect.ProtoMessage
+	if input != nil {
+		// Transform the rpcauth input into the original proto
+		messageType, err := protoregistry.GlobalTypes.FindMessageByURL(input.MessageType)
+		if err != nil {
+			return RPCAuthInput{}, fmt.Errorf("unable to find proto type %v: %v", input.MessageType, err)
+		}
+		redactedMessage = messageType.New().Interface()
+		if err := protojson.Unmarshal([]byte(input.Message), redactedMessage); err != nil {
+			return RPCAuthInput{}, fmt.Errorf("could not marshal input into %v: %v", input.MessageType, err)
+		}
+		redactFields(redactedMessage.ProtoReflect())
+	}
+	marshaled, err := protojson.MarshalOptions{UseProtoNames: true}.Marshal(redactedMessage)
+	if err != nil {
+		return RPCAuthInput{}, status.Errorf(codes.Internal, "error marshalling request for auth: %v", err)
+	}
+	redactedInput.Message = json.RawMessage(marshaled)
+	return redactedInput, nil
+}
+
 // Eval will evalulate the supplied input against the authorization policy, returning
 // nil iff policy evaulation was successful, and the request is permitted, or
 // an appropriate status.Error otherwise. Any input hooks will be executed
@@ -96,29 +206,38 @@ func NewWithPolicy(ctx context.Context, policy string, authzHooks ...RPCAuthzHoo
 func (g *Authorizer) Eval(ctx context.Context, input *RPCAuthInput) error {
 	logger := logr.FromContextOrDiscard(ctx)
 	recorder := metrics.RecorderFromContextOrNoop(ctx)
+
+	redactedInput, err := getRedactedInput(input)
+	if err != nil {
+		return fmt.Errorf("failed to get redacted input: %v", err)
+	}
 	if input != nil {
-		logger.V(2).Info("evaluating authz policy", "input", input)
+		logger.V(2).Info("evaluating authz policy", "input", redactedInput)
 	}
 	if input == nil {
 		err := status.Error(codes.InvalidArgument, "policy input cannot be nil")
-		logger.V(1).Error(err, "failed to evaluate authz policy", "input", input)
+		logger.V(1).Error(err, "failed to evaluate authz policy", "input", redactedInput)
 		recorder.CounterOrLog(ctx, authzFailureInputMissingCounter, 1)
 		return err
 	}
 	for _, hook := range g.hooks {
 		if err := hook.Hook(ctx, input); err != nil {
-			logger.V(1).Error(err, "authz hook error", "input", input)
+			logger.V(1).Error(err, "authz hook error", "input", redactedInput)
 			if _, ok := status.FromError(err); ok {
 				// error is already an appropriate status.Status
 				return err
 			}
 			return status.Errorf(codes.Internal, "authz hook error: %v", err)
 		}
 	}
-	logger.V(2).Info("evaluating authz policy post hooks", "input", input)
+	redactedInput, err = getRedactedInput(input)
+	if err != nil {
+		return fmt.Errorf("failed to get redacted input post hooks: %v", err)
+	}
+	logger.V(2).Info("evaluating authz policy post hooks", "input", redactedInput)
 	result, err := g.policy.Eval(ctx, input)
 	if err != nil {
-		logger.V(1).Error(err, "failed to evaluate authz policy", "input", input)
+		logger.V(1).Error(err, "failed to evaluate authz policy", "input", redactedInput)
 		recorder.CounterOrLog(ctx, authzFailureEvalErrorCounter, 1, attribute.String("method", input.Method))
 		return status.Errorf(codes.Internal, "authz policy evaluation error: %v", err)
 	}
@@ -133,7 +252,7 @@ func (g *Authorizer) Eval(ctx context.Context, input *RPCAuthInput) error {
 			logger.V(1).Error(err, "failed to get hints for authz policy denial", "error", err)
 		}
 	}
-	logger.Info("authz policy evaluation result", "authorizationResult", result, "input", input, "denialHints", hints)
+	logger.Info("authz policy evaluation result", "authorizationResult", result, "input", redactedInput, "denialHints", hints)
 	if !result {
 		errRegister := recorder.Counter(ctx, authzDeniedPolicyCounter, 1, attribute.String("method", input.Method))
 		if errRegister != nil {

auth/opa/rpcauth/rpcauth_test.go

@@ -50,7 +50,7 @@ default allow = false
 
 allow {
   input.method = "/Foo.Bar/Baz"
-  input.type = "Foo.BazRequest"
+  input.type = "Mock.MockRequest"
 }
 
 allow {
@@ -164,7 +164,7 @@ func TestAuthzHook(t *testing.T) {
 			hooks: []RPCAuthzHook{
 				RPCAuthzHookFunc(func(_ context.Context, input *RPCAuthInput) error {
 					input.Method = "/Foo.Bar/Baz"
-					input.MessageType = "Foo.BazRequest"
+					input.MessageType = mockMessageType
 					return nil
 				}),
 			},
@@ -187,10 +187,11 @@ func TestAuthzHook(t *testing.T) {
 			hooks: []RPCAuthzHook{
 				RPCAuthzHookFunc(func(_ context.Context, input *RPCAuthInput) error {
 					input.Method = "/Foo.Bar/Baz"
+					input.MessageType = mockMessageType
 					return nil
 				}),
 				RPCAuthzHookFunc(func(_ context.Context, input *RPCAuthInput) error {
-					input.MessageType = "Foo.BazRequest"
+					input.MessageType = mockMessageType
 					return nil
 				}),
 			},
@@ -249,11 +250,11 @@ func TestAuthzHook(t *testing.T) {
 			hooks: []RPCAuthzHook{
 				RPCAuthzHookFunc(func(_ context.Context, input *RPCAuthInput) error {
 					input.Method = "/Foo.Bar/Baz"
-					input.MessageType = "Foo.BarRequest"
+					input.MessageType = mockMessageType
 					return nil
 				}),
 				RPCAuthzHookFunc(func(_ context.Context, input *RPCAuthInput) error {
-					input.MessageType = "Foo.BazRequest"
+					input.MessageType = mockMessageType
 					return nil
 				}),
 			},

cmd/proxy-server/main.go

@@ -26,6 +26,7 @@ import (
 	"strings"
 
 	"github.com/go-logr/logr"
+	"github.com/go-logr/logr/funcr"
 	"github.com/go-logr/stdr"
 	"go.opentelemetry.io/otel"
 	prometheus_exporter "go.opentelemetry.io/otel/exporters/prometheus"
@@ -98,8 +99,14 @@ func main() {
 		os.Exit(0)
 	}
 
-	logOpts := log.Ldate | log.Ltime | log.Lshortfile
-	logger := stdr.New(log.New(os.Stderr, "", logOpts)).WithName("sanshell-proxy")
+	logger := funcr.NewJSON(func(obj string) {
+		fmt.Println(obj)
+	}, funcr.Options{
+		LogCaller:    funcr.All,
+		LogTimestamp: true,
+		Verbosity:    *verbosity,
+		MaxLogDepth:  99,
+	}).WithName("sansshell-proxy")
 	stdr.SetVerbosity(*verbosity)
 
 	// Setup exporter using the default prometheus registry

services/httpoverrpc/httpoverrpc.proto

@@ -16,6 +16,8 @@
 
 syntax = "proto3";
 
+import "google/protobuf/descriptor.proto";
+
 option go_package = "github.com/Snowflake-Labs/sansshell/httpoverrpc";
 
 package HTTPOverRPC;
@@ -38,7 +40,7 @@ message HostHTTPRequest {
 
 message Header {
   string key = 1;
-  repeated string values = 2;
+  repeated string values = 2 [debug_redact = true];
 }
 
 // HTTPRequest describes the HTTP request