Log all diskcache state with gRPC metadata

This adds an additional log message that will improve visibility of
whether the diskcache is serving stale data or not. The "freshness" of
the cache is determined by the repo's cache state file. The contents of
this file will now be logged whenever it is updated.

Additionally, the path of the cached response on disk will be logged
each time the diskcache is used. This can be used to help determine if
stale data is being served after the cache is expected to be invalid.
Each time the state file changes, we expect a new request file path.

3 files changed, 24 insertions, 5 deletions

diff --git a/changelogs/unreleased/po-diskcache-log-state.yml b/changelogs/unreleased/po-diskcache-log-state.yml
new file mode 100644
index 000000000..a05535d6d
--- /dev/null
+++ b/changelogs/unreleased/po-diskcache-log-state.yml
@@ -0,0 +1,5 @@
+---
+title: Log all diskcache state changes and stream access
+merge_request: 1682
+author:
+type: other
diff --git a/internal/cache/cachedb.go b/internal/cache/cachedb.go
index fc717134a..f756fa31e 100644
--- a/internal/cache/cachedb.go
+++ b/internal/cache/cachedb.go
@@ -9,6 +9,7 @@ import (
 	"sync"
 
 	"github.com/golang/protobuf/proto"
+	grpc_logrus "github.com/grpc-ecosystem/go-grpc-middleware/logging/logrus"
 	"gitlab.com/gitlab-org/gitaly/internal/safe"
 	"gitlab.com/gitlab-org/gitaly/proto/go/gitalypb"
 )
@@ -84,6 +85,10 @@ func (sdb *StreamDB) GetStream(ctx context.Context, repo *gitalypb.Repository, r
 		return nil, err
 	}
 
+	grpc_logrus.Extract(ctx).
+		WithField("stream_path", respPath).
+		Info("getting stream")
+
 	respF, err := os.Open(respPath)
 	switch {
 	case os.IsNotExist(err):
@@ -115,6 +120,10 @@ func (sdb *StreamDB) PutStream(ctx context.Context, repo *gitalypb.Repository, r
 		return err
 	}
 
+	grpc_logrus.Extract(ctx).
+		WithField("stream_path", reqPath).
+		Info("putting stream")
+
 	var n int64
 	isWinner := sdb.af.trackFile(reqPath)
 	defer func() {
diff --git a/internal/cache/keyer.go b/internal/cache/keyer.go
index b7cc5e529..86957c3fe 100644
--- a/internal/cache/keyer.go
+++ b/internal/cache/keyer.go
@@ -13,6 +13,7 @@ import (
 
 	"github.com/golang/protobuf/proto"
 	"github.com/google/uuid"
+	grpc_logrus "github.com/grpc-ecosystem/go-grpc-middleware/logging/logrus"
 	"gitlab.com/gitlab-org/gitaly/internal/config"
 	"gitlab.com/gitlab-org/gitaly/internal/helper"
 	"gitlab.com/gitlab-org/gitaly/internal/safe"
@@ -60,7 +61,7 @@ type lease struct {
 // EndLease will end the lease by removing the pending lease file and updating
 // the key file with the current lease ID.
 func (l lease) EndLease(ctx context.Context) error {
-	_, err := updateLatest(l.repo)
+	_, err := updateLatest(ctx, l.repo)
 	if err != nil {
 		return err
 	}
@@ -75,7 +76,7 @@ func (l lease) EndLease(ctx context.Context) error {
 	return nil
 }
 
-func updateLatest(repo *gitalypb.Repository) (string, error) {
+func updateLatest(ctx context.Context, repo *gitalypb.Repository) (string, error) {
 	repoStatePath, err := getRepoStatePath(repo)
 	if err != nil {
 		return "", err
@@ -105,6 +106,10 @@ func updateLatest(repo *gitalypb.Repository) (string, error) {
 		return "", err
 	}
 
+	grpc_logrus.Extract(ctx).
+		WithField("diskcache", nextGenID).
+		Infof("diskcache state change")
+
 	return nextGenID, nil
 }
 
@@ -164,7 +169,7 @@ func (LeaseKeyer) KeyPath(ctx context.Context, repo *gitalypb.Repository, req pr
 		return "", countErr(ErrPendingExists)
 	}
 
-	genID, err := currentGenID(repo)
+	genID, err := currentGenID(ctx, repo)
 	if err != nil {
 		return "", err
 	}
@@ -262,7 +267,7 @@ func currentLeases(repo *gitalypb.Repository) ([]os.FileInfo, error) {
 	return pendings, nil
 }
 
-func currentGenID(repo *gitalypb.Repository) (string, error) {
+func currentGenID(ctx context.Context, repo *gitalypb.Repository) (string, error) {
 	repoStatePath, err := getRepoStatePath(repo)
 	if err != nil {
 		return "", err
@@ -272,7 +277,7 @@ func currentGenID(repo *gitalypb.Repository) (string, error) {
 	switch {
 	case os.IsNotExist(err):
 		// latest file doesn't exist, so create one
-		return updateLatest(repo)
+		return updateLatest(ctx, repo)
 	case err == nil:
 		return string(latestBytes), nil
 	default: