From caa2f9ccf1f06f35c767276cb6b8051cd8e02df1 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Sybren=20A=2E=20St=C3=BCvel?= <sybren@blender.org>
Date: Wed, 31 May 2023 13:54:28 +0200
Subject: [PATCH] Shaman: improve logging & checking of timestamps

Add more logging of timestamps in the actual code, and a few sanity
checks in unit tests.

These were useful while trying to find the root cause of #104218 and might
be useful in the future too. The solution to that issue will be committed
later.
---
 pkg/shaman/checkout/manager.go |  7 ++++---
 pkg/shaman/cleanup.go          |  4 +++-
 pkg/shaman/cleanup_test.go     | 26 ++++++++++++++++++++++++--
 3 files changed, 31 insertions(+), 6 deletions(-)

diff --git a/pkg/shaman/checkout/manager.go b/pkg/shaman/checkout/manager.go
index 3490dda6..1e1238a3 100644
--- a/pkg/shaman/checkout/manager.go
+++ b/pkg/shaman/checkout/manager.go
@@ -277,15 +277,16 @@ func touchFile(blobPath string) error {
 	if blobPath == "" {
 		return os.ErrInvalid
 	}
-	now := time.Now()
+	logger := log.With().Str("file", blobPath).Logger()
+	logger.Debug().Msg("shaman: touching file")
 
+	now := time.Now()
 	err := touch.Touch(blobPath)
 	if err != nil {
 		return err
 	}
 
-	duration := time.Now().Sub(now)
-	logger := log.With().Str("file", blobPath).Logger()
+	duration := time.Since(now)
 	if duration > 1*time.Second {
 		logger.Warn().Str("duration", duration.String()).Msg("done touching but took a long time")
 	}
diff --git a/pkg/shaman/cleanup.go b/pkg/shaman/cleanup.go
index dfcdaecc..059a98be 100644
--- a/pkg/shaman/cleanup.go
+++ b/pkg/shaman/cleanup.go
@@ -236,7 +236,9 @@ func (s *Server) gcDeleteOldFiles(doDryRun bool, oldFiles mtimeMap, logger zerol
 				pathLogger.Warn().Err(err).Msg("unable to stat to-be-deleted file")
 			}
 		} else if stat.ModTime().After(lastSeenModTime) {
-			pathLogger.Info().Msg("not deleting recently-touched file")
+			pathLogger.Info().
+				Stringer("modTime", stat.ModTime()).
+				Msg("not deleting recently-touched file")
 			continue
 		} else {
 			deletedBytes += stat.Size()
diff --git a/pkg/shaman/cleanup_test.go b/pkg/shaman/cleanup_test.go
index 746d57e9..ea68208b 100644
--- a/pkg/shaman/cleanup_test.go
+++ b/pkg/shaman/cleanup_test.go
@@ -24,6 +24,7 @@ package shaman
 
 import (
 	"errors"
+	"fmt"
 	"io/fs"
 	"os"
 	"path/filepath"
@@ -44,7 +45,13 @@ func createTestShaman() (*Server, func()) {
 }
 
 func makeOld(shaman *Server, expectOld mtimeMap, relPath string) {
-	oldTime := time.Now().Add(-2 * shaman.config.GarbageCollect.MaxAge)
+	if shaman.config.GarbageCollect.MaxAge < 2 {
+		panic(fmt.Sprintf(
+			"shaman.config.GarbageCollect.MaxAge is unusably low: %v",
+			shaman.config.GarbageCollect.MaxAge))
+	}
+	age := -2 * shaman.config.GarbageCollect.MaxAge
+	oldTime := time.Now().Add(age)
 	absPath := filepath.Join(shaman.config.FileStorePath(), relPath)
 
 	err := os.Chtimes(absPath, oldTime, oldTime)
@@ -57,7 +64,22 @@ func makeOld(shaman *Server, expectOld mtimeMap, relPath string) {
 	if err != nil {
 		panic(err)
 	}
-	expectOld[absPath] = stat.ModTime()
+	osModTime := stat.ModTime()
+	expectOld[absPath] = osModTime
+
+	log.Debug().
+		Str("relPath", relPath).
+		Stringer("age", age).
+		Stringer("stamp", oldTime).
+		Stringer("actual", osModTime).
+		Msg("makeOld")
+
+	// Sanity check that the timestamp on disk is somewhat similar to what we expected.
+	timediff := osModTime.Sub(oldTime).Abs()
+	if timediff.Seconds() > 1 {
+		panic(fmt.Sprintf("unable to set timestamp of %s:\n      set=%q but\n   actual=%q, difference is %s",
+			absPath, oldTime, osModTime, timediff))
+	}
 }
 
 func TestGCCanary(t *testing.T) {