chore: debug missing digests chunking issues (#11504)

`Read` requests shouldn't fail, otherwise they can cause missing digest
issues. There aren't many per day, and there are even less that are
above the chunking threshold, so I don't expect many logs here.

To help debug some of the issues we're seeing, this PR adds logs and
metrics for Read requests that fail during the chunking path.

Author: tyler-french

enterprise/server/byte_stream_server_proxy/byte_stream_server_proxy.go

@@ -177,8 +177,10 @@ func (s *ByteStreamServerProxy) read(ctx context.Context, req *bspb.ReadRequest,
 		// If chunking is enabled and the blob is large enough, try to read the chunks.
 		// TODO(buildbuddy-internal#6426): Once most large blobs are chunked, consider
 		// attempting the chunked read first.
+		var chunkedErr error
 		if s.shouldReadChunked(ctx, req, rn) {
-			chunkMetrics, chunkedErr := s.readChunked(ctx, req, stream, rn)
+			chunkMetrics, err := s.readChunked(ctx, req, stream, rn)
+			chunkedErr = err
 			if chunkedErr == nil {
 				return readMetrics{
 					cacheStatus:  metrics.MissStatusLabel,
@@ -189,15 +191,18 @@ func (s *ByteStreamServerProxy) read(ctx context.Context, req *bspb.ReadRequest,
 					chunksLocal:  chunkMetrics.chunksLocal,
 					chunksRemote: chunkMetrics.chunksRemote,
 				}, nil
-			} else if !status.IsNotFoundError(chunkedErr) {
-				log.CtxWarningf(ctx, "Error reading chunked blob %s: %s", rn.DownloadString(), chunkedErr)
 			}
 		}
 
+		remoteErr := s.readRemoteWriteLocal(req, stream)
+		if remoteErr != nil && chunkedErr != nil {
+			// TODO(buildbuddy-internal#6426): Remove once root cause for missing digests is found.
+			log.CtxWarningf(ctx, "Proxy chunked read failed for %s (remote fallback also failed): chunkedErr=%s remoteErr=%s", rn.DownloadString(), chunkedErr, remoteErr)
+		}
 		return readMetrics{
 			cacheStatus: metrics.MissStatusLabel,
 			compressor:  rn.GetCompressor().String(),
-		}, s.readRemoteWriteLocal(req, stream)
+		}, remoteErr
 	} else {
 		return readMetrics{
 			cacheStatus: metrics.HitStatusLabel,
@@ -229,6 +234,10 @@ func (s *ByteStreamServerProxy) readChunked(ctx context.Context, req *bspb.ReadR
 	// Using the interface.Cache requires namespacing the AC keys by group ID.
 	ctx, err := prefix.AttachUserPrefixToContext(ctx, s.authenticator)
 	if err != nil {
+		metrics.ByteStreamProxyChunkedReadFailures.With(prometheus.Labels{
+			metrics.ChunkedFailureReasonLabel: "auth_error",
+			metrics.StatusHumanReadableLabel:  status.MetricsLabel(err),
+		}).Inc()
 		return m, err
 	}
 
@@ -242,17 +251,29 @@ func (s *ByteStreamServerProxy) readChunked(ctx context.Context, req *bspb.ReadR
 	}
 	splitResp, err := s.remoteCAS.SplitBlob(ctx, splitReq)
 	if err != nil {
+		metrics.ByteStreamProxyChunkedReadFailures.With(prometheus.Labels{
+			metrics.ChunkedFailureReasonLabel: "split_blob_error",
+			metrics.StatusHumanReadableLabel:  status.MetricsLabel(err),
+		}).Inc()
 		return m, err
 	}
 	for _, chunkDigest := range splitResp.GetChunkDigests() {
 		chunkRN := digest.NewCASResourceName(chunkDigest, instanceName, digestFunction)
 		chunkRN.SetCompressor(rn.GetCompressor())
 		if err := s.local.ReadCASResource(ctx, chunkRN, 0, 0, stream); status.IsNotFoundError(err) {
 			if err := s.readRemoteWriteLocal(&bspb.ReadRequest{ResourceName: chunkRN.DownloadString()}, stream); err != nil {
+				metrics.ByteStreamProxyChunkedReadFailures.With(prometheus.Labels{
+					metrics.ChunkedFailureReasonLabel: "chunk_remote_fetch_error",
+					metrics.StatusHumanReadableLabel:  status.MetricsLabel(err),
+				}).Inc()
 				return m, err
 			}
 			m.chunksRemote++
 		} else if err != nil {
+			metrics.ByteStreamProxyChunkedReadFailures.With(prometheus.Labels{
+				metrics.ChunkedFailureReasonLabel: "chunk_local_read_error",
+				metrics.StatusHumanReadableLabel:  status.MetricsLabel(err),
+			}).Inc()
 			return m, err
 		} else {
 			m.chunksLocal++

server/metrics/metrics.go

@@ -179,6 +179,8 @@ const (
 	// Whether the request was handled using chunking
 	ChunkedLabel = "chunked"
 
+	ChunkedFailureReasonLabel = "reason"
+
 	// The name of the table in Clickhouse
 	ClickhouseTableName = "clickhouse_table_name"
 
@@ -3685,6 +3687,26 @@ var (
 		CompressionType,
 	})
 
+	ByteStreamProxyChunkedReadFailures = promauto.NewCounterVec(prometheus.CounterOpts{
+		Namespace: bbNamespace,
+		Subsystem: "proxy",
+		Name:      "byte_stream_chunked_read_failures",
+		Help:      "Number of chunked read attempts that failed, by failure reason.",
+	}, []string{
+		ChunkedFailureReasonLabel,
+		StatusHumanReadableLabel,
+	})
+
+	ByteStreamServerChunkedReadFailures = promauto.NewCounterVec(prometheus.CounterOpts{
+		Namespace: bbNamespace,
+		Subsystem: "remote_cache",
+		Name:      "byte_stream_chunked_read_failures",
+		Help:      "Number of chunked read attempts that failed on the backend, by failure reason.",
+	}, []string{
+		ChunkedFailureReasonLabel,
+		StatusHumanReadableLabel,
+	})
+
 	CapabilitiesProxiedRequests = promauto.NewCounterVec(prometheus.CounterOpts{
 		Namespace: bbNamespace,
 		Subsystem: "proxy",

server/remote_cache/byte_stream_server/BUILD

@@ -10,6 +10,7 @@ go_library(
         "//proto:remote_execution_go_proto",
         "//server/environment",
         "//server/interfaces",
+        "//server/metrics",
         "//server/real_environment",
         "//server/remote_cache/chunking",
         "//server/remote_cache/config",
@@ -26,6 +27,7 @@ go_library(
         "//server/util/prefix",
         "//server/util/quota",
         "//server/util/status",
+        "@com_github_prometheus_client_golang//prometheus",
         "@org_golang_google_genproto_googleapis_bytestream//:bytestream",
         "@org_golang_google_grpc//peer",
     ],

server/remote_cache/byte_stream_server/byte_stream_server.go

@@ -8,6 +8,7 @@ import (
 
 	"github.com/buildbuddy-io/buildbuddy/server/environment"
 	"github.com/buildbuddy-io/buildbuddy/server/interfaces"
+	"github.com/buildbuddy-io/buildbuddy/server/metrics"
 	"github.com/buildbuddy-io/buildbuddy/server/real_environment"
 	"github.com/buildbuddy-io/buildbuddy/server/remote_cache/chunking"
 	"github.com/buildbuddy-io/buildbuddy/server/remote_cache/digest"
@@ -23,6 +24,7 @@ import (
 	"github.com/buildbuddy-io/buildbuddy/server/util/prefix"
 	"github.com/buildbuddy-io/buildbuddy/server/util/quota"
 	"github.com/buildbuddy-io/buildbuddy/server/util/status"
+	"github.com/prometheus/client_golang/prometheus"
 	"google.golang.org/grpc/peer"
 
 	cappb "github.com/buildbuddy-io/buildbuddy/proto/capability"
@@ -207,8 +209,16 @@ func (s *ByteStreamServer) attemptReadChunked(ctx context.Context, rn *digest.CA
 
 	rns := manifest.ChunkResourceNames()
 	if missing, err := s.cache.FindMissing(ctx, rns); err != nil {
+		metrics.ByteStreamServerChunkedReadFailures.With(prometheus.Labels{
+			metrics.ChunkedFailureReasonLabel: "chunk_find_missing_error",
+			metrics.StatusHumanReadableLabel:  status.MetricsLabel(err),
+		}).Inc()
 		return nil, err
 	} else if len(missing) > 0 {
+		metrics.ByteStreamServerChunkedReadFailures.With(prometheus.Labels{
+			metrics.ChunkedFailureReasonLabel: "chunks_missing",
+			metrics.StatusHumanReadableLabel:  "NotFound",
+		}).Inc()
 		return nil, status.NotFoundErrorf("chunks missing from manifest for %q: %q", rn.DownloadString(), chunking.DigestsSummary(missing))
 	}
 
@@ -218,6 +228,10 @@ func (s *ByteStreamServer) attemptReadChunked(ctx context.Context, rn *digest.CA
 		chunkRN.SetCompressor(rn.GetCompressor())
 		rc, err := s.cache.Reader(ctx, chunkRN.ToProto(), 0, 0)
 		if err != nil {
+			metrics.ByteStreamServerChunkedReadFailures.With(prometheus.Labels{
+				metrics.ChunkedFailureReasonLabel: "chunk_read_error",
+				metrics.StatusHumanReadableLabel:  status.MetricsLabel(err),
+			}).Inc()
 			for _, openCloser := range rcs {
 				openCloser.Close()
 			}