feat: improve new action cache logging (#2474)

* feat: improve new action cache logging

* Test logging failure cases

---------

Co-authored-by: mergify[bot] <37929162+mergify[bot]@users.noreply.github.com>

Author: ChristopherHX

pkg/runner/action_cache.go

@@ -19,6 +19,7 @@ import (
 	"github.com/go-git/go-git/v5/plumbing/object"
 	"github.com/go-git/go-git/v5/plumbing/transport"
 	"github.com/go-git/go-git/v5/plumbing/transport/http"
+	"github.com/nektos/act/pkg/common"
 )
 
 type ActionCache interface {
@@ -31,17 +32,23 @@ type GoGitActionCache struct {
 }
 
 func (c GoGitActionCache) Fetch(ctx context.Context, cacheDir, url, ref, token string) (string, error) {
+	logger := common.Logger(ctx)
+
 	gitPath := path.Join(c.Path, safeFilename(cacheDir)+".git")
+
+	logger.Infof("GoGitActionCache fetch %s with ref %s at %s", url, ref, gitPath)
+
 	gogitrepo, err := git.PlainInit(gitPath, true)
 	if errors.Is(err, git.ErrRepositoryAlreadyExists) {
+		logger.Debugf("GoGitActionCache cache hit %s with ref %s at %s", url, ref, gitPath)
 		gogitrepo, err = git.PlainOpen(gitPath)
 	}
 	if err != nil {
-		return "", err
+		return "", fmt.Errorf("GoGitActionCache failed to open bare git %s with ref %s at %s: %w", url, ref, gitPath, err)
 	}
 	tmpBranch := make([]byte, 12)
 	if _, err := rand.Read(tmpBranch); err != nil {
-		return "", err
+		return "", fmt.Errorf("GoGitActionCache failed to generate random tmp branch %s with ref %s at %s: %w", url, ref, gitPath, err)
 	}
 	branchName := hex.EncodeToString(tmpBranch)
 
@@ -59,7 +66,7 @@ func (c GoGitActionCache) Fetch(ctx context.Context, cacheDir, url, ref, token s
 		},
 	})
 	if err != nil {
-		return "", err
+		return "", fmt.Errorf("GoGitActionCache failed to create remote %s with ref %s at %s: %w", url, ref, gitPath, err)
 	}
 	defer func() {
 		_ = gogitrepo.DeleteBranch(branchName)
@@ -71,12 +78,13 @@ func (c GoGitActionCache) Fetch(ctx context.Context, cacheDir, url, ref, token s
 		Auth:  auth,
 		Force: true,
 	}); err != nil {
-		return "", err
+		return "", fmt.Errorf("GoGitActionCache failed to fetch %s with ref %s at %s: %w", url, ref, gitPath, err)
 	}
 	hash, err := gogitrepo.ResolveRevision(plumbing.Revision(branchName))
 	if err != nil {
-		return "", err
+		return "", fmt.Errorf("GoGitActionCache failed to resolve sha %s with ref %s at %s: %w", url, ref, gitPath, err)
 	}
+	logger.Infof("GoGitActionCache fetch %s with ref %s at %s resolved to %s", url, ref, gitPath, hash.String())
 	return hash.String(), nil
 }
 
@@ -119,22 +127,27 @@ func (g *GitFileInfo) Sys() any {
 }
 
 func (c GoGitActionCache) GetTarArchive(ctx context.Context, cacheDir, sha, includePrefix string) (io.ReadCloser, error) {
+	logger := common.Logger(ctx)
+
 	gitPath := path.Join(c.Path, safeFilename(cacheDir)+".git")
+
+	logger.Infof("GoGitActionCache get content %s with sha %s subpath %s at %s", cacheDir, sha, includePrefix, gitPath)
+
 	gogitrepo, err := git.PlainOpen(gitPath)
 	if err != nil {
-		return nil, err
+		return nil, fmt.Errorf("GoGitActionCache failed to open bare git %s with sha %s subpath %s at %s: %w", cacheDir, sha, includePrefix, gitPath, err)
 	}
 	commit, err := gogitrepo.CommitObject(plumbing.NewHash(sha))
 	if err != nil {
-		return nil, err
+		return nil, fmt.Errorf("GoGitActionCache failed to get commit %s with sha %s subpath %s at %s: %w", cacheDir, sha, includePrefix, gitPath, err)
 	}
 	t, err := commit.Tree()
 	if err != nil {
-		return nil, err
+		return nil, fmt.Errorf("GoGitActionCache failed to open git tree %s with sha %s subpath %s at %s: %w", cacheDir, sha, includePrefix, gitPath, err)
 	}
 	files, err := commit.Files()
 	if err != nil {
-		return nil, err
+		return nil, fmt.Errorf("GoGitActionCache failed to list files %s with sha %s subpath %s at %s: %w", cacheDir, sha, includePrefix, gitPath, err)
 	}
 	rpipe, wpipe := io.Pipe()
 	// Interrupt io.Copy using ctx

pkg/runner/action_cache_offline_mode.go

@@ -7,15 +7,21 @@ import (
 
 	git "github.com/go-git/go-git/v5"
 	"github.com/go-git/go-git/v5/plumbing"
+	"github.com/nektos/act/pkg/common"
 )
 
 type GoGitActionCacheOfflineMode struct {
 	Parent GoGitActionCache
 }
 
 func (c GoGitActionCacheOfflineMode) Fetch(ctx context.Context, cacheDir, url, ref, token string) (string, error) {
-	sha, fetchErr := c.Parent.Fetch(ctx, cacheDir, url, ref, token)
+	logger := common.Logger(ctx)
+
 	gitPath := path.Join(c.Parent.Path, safeFilename(cacheDir)+".git")
+
+	logger.Infof("GoGitActionCacheOfflineMode fetch content %s with ref %s at %s", url, ref, gitPath)
+
+	sha, fetchErr := c.Parent.Fetch(ctx, cacheDir, url, ref, token)
 	gogitrepo, err := git.PlainOpen(gitPath)
 	if err != nil {
 		return "", fetchErr

pkg/runner/action_cache_test.go

@@ -52,7 +52,7 @@ func TestActionCache(t *testing.T) {
 		},
 	}
 	for _, c := range refs {
-		t.Run(c.Name, func(t *testing.T) {
+		t.Run(c.Name, func(_ *testing.T) {
 			sha, err := cache.Fetch(ctx, c.CacheDir, c.Repo, c.Ref, "")
 			if !a.NoError(err) || !a.NotEmpty(sha) {
 				return
@@ -75,3 +75,72 @@ func TestActionCache(t *testing.T) {
 		})
 	}
 }
+
+func TestActionCacheFailures(t *testing.T) {
+	a := assert.New(t)
+	cache := &GoGitActionCache{
+		Path: os.TempDir(),
+	}
+	ctx := context.Background()
+	cacheDir := "nektos/act-test-actions"
+	repo := "https://github.com/nektos/act-test-actions-not-exist"
+	repoExist := "https://github.com/nektos/act-test-actions"
+	refs := []struct {
+		Name     string
+		CacheDir string
+		Repo     string
+		Ref      string
+	}{
+		{
+			Name:     "Fetch Branch Name",
+			CacheDir: cacheDir,
+			Repo:     repo,
+			Ref:      "main",
+		},
+		{
+			Name:     "Fetch Branch Name Absolutely",
+			CacheDir: cacheDir,
+			Repo:     repo,
+			Ref:      "refs/heads/main",
+		},
+		{
+			Name:     "Fetch HEAD",
+			CacheDir: cacheDir,
+			Repo:     repo,
+			Ref:      "HEAD",
+		},
+		{
+			Name:     "Fetch Sha",
+			CacheDir: cacheDir,
+			Repo:     repo,
+			Ref:      "de984ca37e4df4cb9fd9256435a3b82c4a2662b1",
+		},
+		{
+			Name:     "Fetch Branch Name no existing",
+			CacheDir: cacheDir,
+			Repo:     repoExist,
+			Ref:      "main2",
+		},
+		{
+			Name:     "Fetch Branch Name Absolutely no existing",
+			CacheDir: cacheDir,
+			Repo:     repoExist,
+			Ref:      "refs/heads/main2",
+		},
+		{
+			Name:     "Fetch Sha no existing",
+			CacheDir: cacheDir,
+			Repo:     repoExist,
+			Ref:      "de984ca37e4df4cb9fd9256435a3b82c4a2662b2",
+		},
+	}
+	for _, c := range refs {
+		t.Run(c.Name, func(t *testing.T) {
+			_, err := cache.Fetch(ctx, c.CacheDir, c.Repo, c.Ref, "")
+			t.Logf("%s\n", err)
+			if !a.Error(err) {
+				return
+			}
+		})
+	}
+}

pkg/runner/local_repository_cache.go

@@ -12,6 +12,7 @@ import (
 	"path/filepath"
 	"strings"
 
+	"github.com/nektos/act/pkg/common"
 	"github.com/nektos/act/pkg/filecollector"
 )
 
@@ -22,22 +23,29 @@ type LocalRepositoryCache struct {
 }
 
 func (l *LocalRepositoryCache) Fetch(ctx context.Context, cacheDir, url, ref, token string) (string, error) {
+	logger := common.Logger(ctx)
+	logger.Debugf("LocalRepositoryCache fetch %s with ref %s", url, ref)
 	if dest, ok := l.LocalRepositories[fmt.Sprintf("%s@%s", url, ref)]; ok {
+		logger.Infof("LocalRepositoryCache matched %s with ref %s to %s", url, ref, dest)
 		l.CacheDirCache[fmt.Sprintf("%s@%s", cacheDir, ref)] = dest
 		return ref, nil
 	}
 	if purl, err := goURL.Parse(url); err == nil {
 		if dest, ok := l.LocalRepositories[fmt.Sprintf("%s@%s", strings.TrimPrefix(purl.Path, "/"), ref)]; ok {
+			logger.Infof("LocalRepositoryCache matched %s with ref %s to %s", url, ref, dest)
 			l.CacheDirCache[fmt.Sprintf("%s@%s", cacheDir, ref)] = dest
 			return ref, nil
 		}
 	}
+	logger.Infof("LocalRepositoryCache not matched %s with Ref %s", url, ref)
 	return l.Parent.Fetch(ctx, cacheDir, url, ref, token)
 }
 
 func (l *LocalRepositoryCache) GetTarArchive(ctx context.Context, cacheDir, sha, includePrefix string) (io.ReadCloser, error) {
+	logger := common.Logger(ctx)
 	// sha is mapped to ref in fetch if there is a local override
 	if dest, ok := l.CacheDirCache[fmt.Sprintf("%s@%s", cacheDir, sha)]; ok {
+		logger.Infof("LocalRepositoryCache read cachedir %s with ref %s and subpath %s from %s", cacheDir, sha, includePrefix, dest)
 		srcPath := filepath.Join(dest, includePrefix)
 		buf := &bytes.Buffer{}
 		tw := tar.NewWriter(buf)
@@ -87,5 +95,6 @@ func (l *LocalRepositoryCache) GetTarArchive(ctx context.Context, cacheDir, sha,
 		}
 		return io.NopCloser(buf), nil
 	}
+	logger.Infof("LocalRepositoryCache not matched cachedir %s with Ref %s and subpath %s", cacheDir, sha, includePrefix)
 	return l.Parent.GetTarArchive(ctx, cacheDir, sha, includePrefix)
 }