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)
+	duration := time.Since(now)
-	logger := log.With().Str("file", blobPath).Logger()
 	if duration > 1*time.Second {
 		logger.Warn().Str("duration", duration.String()).Msg("done touching but took a long time")
 	}

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()
@@ -246,7 +248,13 @@ func (s *Server) gcDeleteOldFiles(doDryRun bool, oldFiles mtimeMap, logger zerol
 			pathLogger.Info().Msg("would delete unused file")
 		} else {
 			pathLogger.Info().Msg("deleting unused file")
-			if err := s.fileStore.RemoveStoredFile(path); err == nil {
+			err := s.fileStore.RemoveStoredFile(path)
+			switch {
+			case errors.Is(err, fs.ErrNotExist):
+				pathLogger.Debug().Msg("shaman: unused file disappeared before we could remove it during GC run")
+			case err != nil:
+				pathLogger.Error().Err(err).Msg("shaman: unable to delete unused file during GC run")
+			default:
 				deletedFiles++
 			}
 		}

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) {

pkg/shaman/filestore/testing.go

@@ -23,6 +23,8 @@
 package filestore
 
 import (
+	"fmt"
+	"io"
 	"io/ioutil"
 	"os"
 	"path/filepath"
@@ -75,7 +77,7 @@ func (s *Store) MustStoreFileForTest(checksum string, filesize int64, contents [
 	}
 }
 
-// LinkTestFileStore creates a copy of _test_file_store by hard-linking files into a temporary directory.
+// LinkTestFileStore creates a copy of _test_file_store in a temporary directory.
 // Panics if there are any errors.
 func LinkTestFileStore(cloneTo string) {
 	_, myFilename, _, _ := runtime.Caller(0)
@@ -96,7 +98,7 @@ func LinkTestFileStore(cloneTo string) {
 		if info.IsDir() {
 			return os.MkdirAll(targetPath, 0755)
 		}
-		err = os.Link(visitPath, targetPath)
+		err = copyFile(visitPath, targetPath)
 		if err != nil {
 			return err
 		}
@@ -107,3 +109,33 @@ func LinkTestFileStore(cloneTo string) {
 		panic(err)
 	}
 }
+
+func copyFile(sourcePath, destPath string) error {
+	// Open the source file.
+	srcFile, err := os.Open(sourcePath)
+	if err != nil {
+		return fmt.Errorf("could not open %q: %w", sourcePath, err)
+	}
+	defer srcFile.Close()
+
+	// Create the destination file.
+	destFile, err := os.Create(destPath)
+	if err != nil {
+		return fmt.Errorf("could not create %q: %w", destPath, err)
+	}
+	defer destFile.Close()
+
+	// Copy the contents from source to destination.
+	_, err = io.Copy(destFile, srcFile)
+	if err != nil {
+		return fmt.Errorf("could not copy contents of %q to %q: %w", sourcePath, destPath, err)
+	}
+
+	// Flush any buffered data to ensure completion.
+	err = destFile.Sync()
+	if err != nil {
+		return fmt.Errorf("could not sync buffer of %q to disk: %w", destPath, err)
+	}
+
+	return nil
+}