Fix NotFound errors logged at ERROR when wrapped in multierror

grpcutil/logging.go

@@ -3,6 +3,7 @@ package grpcutil
 
 import (
 	"context"
+	"errors"
 	"time"
 
 	cli "github.com/peterebden/go-cli-init/v4/logging"
@@ -73,10 +74,10 @@ func LogUnaryRequests(ctx context.Context, req interface{}, info *grpc.UnaryServ
 	start := time.Now()
 	resp, err := handler(ctx, req)
 	if err != nil {
-		if status.Code(err) != codes.NotFound {
-			log.Error("Error handling %s: %s", info.FullMethod, err)
+		if hasGRPCCode(err, codes.NotFound) {
+			log.Debug("Not found on %s: %v", info.FullMethod, err)
 		} else {
-			log.Debug("Not found on %s: %s", info.FullMethod, err)
+			log.Error("Error handling %s: %v", info.FullMethod, err)
 		}
 	} else {
 		log.Debug("Handled %s successfully in %s", info.FullMethod, time.Since(start))
@@ -89,13 +90,32 @@ func LogStreamRequests(srv interface{}, ss grpc.ServerStream, info *grpc.StreamS
 	start := time.Now()
 	err := handler(srv, ss)
 	if err != nil {
-		if status.Code(err) != codes.NotFound {
-			log.Error("Error handling %s: %s", info.FullMethod, err)
+		if hasGRPCCode(err, codes.NotFound) {
+			log.Debug("Not found on %s: %v", info.FullMethod, err)
 		} else {
-			log.Debug("Not found on %s: %s", info.FullMethod, err)
+			log.Error("Error handling %s: %v", info.FullMethod, err)
 		}
 	} else {
 		log.Debug("Handled %s successfully in %s", info.FullMethod, time.Since(start))
 	}
 	return err
 }
+
+// grpcStatusError is the interface implemented by gRPC status errors.
+type grpcStatusError interface {
+	GRPCStatus() *status.Status
+}
+
+// hasGRPCCode reports whether err or any error in its tree has the given gRPC
+// status code. This handles errors wrapped by multierror or fmt.Errorf("%w")
+// where status.Code() alone would return codes.Unknown.
+func hasGRPCCode(err error, code codes.Code) bool {
+	if status.Code(err) == code {
+		return true
+	}
+	var se grpcStatusError
+	if errors.As(err, &se) {
+		return se.GRPCStatus().Code() == code
+	}
+	return false
+}

grpcutil/logging_test.go

@@ -0,0 +1,49 @@
+package grpcutil
+
+import (
+	"fmt"
+	"testing"
+
+	"github.com/hashicorp/go-multierror"
+	"github.com/stretchr/testify/assert"
+	"google.golang.org/grpc/codes"
+	"google.golang.org/grpc/status"
+)
+
+func TestHasGRPCCode_DirectStatus(t *testing.T) {
+	err := status.Errorf(codes.NotFound, "blob not found")
+	assert.True(t, hasGRPCCode(err, codes.NotFound))
+	assert.False(t, hasGRPCCode(err, codes.Internal))
+}
+
+func TestHasGRPCCode_MultierrorWrapped(t *testing.T) {
+	// With multiple errors, multierror wraps them in a way that loses the
+	// gRPC status code from status.Code's perspective.
+	inner1 := status.Errorf(codes.NotFound, "blob abc123 not found")
+	inner2 := status.Errorf(codes.NotFound, "blob def456 not found")
+	var multi error
+	multi = multierror.Append(multi, inner1, inner2)
+	// status.Code sees NotFound because multierror implements Unwrap
+	// but the important thing is hasGRPCCode finds it either way
+	assert.True(t, hasGRPCCode(multi, codes.NotFound))
+	assert.False(t, hasGRPCCode(multi, codes.Internal))
+}
+
+func TestHasGRPCCode_MultierrorGroup(t *testing.T) {
+	// This mirrors how elan's getTree uses multierror.Group
+	var g multierror.Group
+	g.Go(func() error {
+		return status.Errorf(codes.NotFound, "blob def456 not found")
+	})
+	err := g.Wait().ErrorOrNil()
+	assert.True(t, hasGRPCCode(err, codes.NotFound))
+}
+
+func TestHasGRPCCode_NonGRPCError(t *testing.T) {
+	err := fmt.Errorf("some random error")
+	assert.False(t, hasGRPCCode(err, codes.NotFound))
+}
+
+func TestHasGRPCCode_Nil(t *testing.T) {
+	assert.False(t, hasGRPCCode(nil, codes.NotFound))
+}