add debug logs to LocalActionsCache and RuleAction

action_metadata.go

@@ -2,6 +2,7 @@ package actionlint
 
 import (
 	"fmt"
+	"io"
 	"io/ioutil"
 	"os"
 	"path/filepath"
@@ -47,16 +48,26 @@ type LocalActionsCache struct {
 	mu    sync.RWMutex
 	proj  *Project // might be nil
 	cache map[string]*ActionMetadata
+	dbg   io.Writer
 }
 
 // NewLocalActionsCache creates new LocalActionsCache instance.
-func NewLocalActionsCache(proj *Project) *LocalActionsCache {
+func NewLocalActionsCache(proj *Project, dbg io.Writer) *LocalActionsCache {
 	return &LocalActionsCache{
 		proj:  proj,
 		cache: map[string]*ActionMetadata{},
+		dbg:   dbg,
 	}
 }
 
+func (c *LocalActionsCache) debug(format string, args ...interface{}) {
+	if c.dbg == nil {
+		return
+	}
+	format = "[LocalActionsCache] " + format + "\n"
+	fmt.Fprintf(c.dbg, format, args...)
+}
+
 func (c *LocalActionsCache) readCache(key string) (*ActionMetadata, bool) {
 	c.mu.RLock()
 	m, ok := c.cache[key]
@@ -82,6 +93,7 @@ func (c *LocalActionsCache) FindMetadata(spec string) (*ActionMetadata, error) {
 	}
 
 	if m, ok := c.readCache(spec); ok {
+		c.debug("Cache hit for %s: %v", spec, m)
 		return m, nil
 	}
 
@@ -99,6 +111,8 @@ func (c *LocalActionsCache) FindMetadata(spec string) (*ActionMetadata, error) {
 		return nil, fmt.Errorf("action.yml in %q is invalid: %s", dir, msg)
 	}
 
+	c.debug("New metadata parsed from action %s: %v", dir, &meta)
+
 	c.writeCache(spec, &meta)
 	return &meta, nil
 }

action_metadata_test.go

@@ -1,6 +1,7 @@
 package actionlint
 
 import (
+	"bytes"
 	"path/filepath"
 	"strings"
 	"testing"
@@ -32,7 +33,7 @@ func testGetWantedActionMetadata() *ActionMetadata {
 
 func TestLocalActionsFindMetadata(t *testing.T) {
 	proj := &Project{filepath.Join("testdata", "action_metadata"), nil}
-	c := NewLocalActionsCache(proj)
+	c := NewLocalActionsCache(proj, nil)
 
 	want := testGetWantedActionMetadata()
 	for _, spec := range []string{"./action-yml", "./action-yaml"} {
@@ -83,7 +84,7 @@ func TestLocalActionsFindMetadata(t *testing.T) {
 func TestLocalActionsFindConcurrently(t *testing.T) {
 	n := 10
 	proj := &Project{filepath.Join("testdata", "action_metadata"), nil}
-	c := NewLocalActionsCache(proj)
+	c := NewLocalActionsCache(proj, nil)
 	ret := make(chan *ActionMetadata)
 	err := make(chan error)
 
@@ -130,7 +131,7 @@ func TestLocalActionsFindConcurrently(t *testing.T) {
 }
 
 func TestLocalActionsProjectIsNil(t *testing.T) {
-	c := NewLocalActionsCache(nil)
+	c := NewLocalActionsCache(nil, nil)
 	for _, spec := range []string{"./action-yml", "this-action-does-not-exit"} {
 		m, err := c.FindMetadata(spec)
 		if err != nil {
@@ -144,7 +145,7 @@ func TestLocalActionsProjectIsNil(t *testing.T) {
 
 func TestLocalActionsIgnoreRemoteActions(t *testing.T) {
 	proj := &Project{filepath.Join("testdata", "action_metadata"), nil}
-	c := NewLocalActionsCache(proj)
+	c := NewLocalActionsCache(proj, nil)
 	for _, spec := range []string{"actions/checkout@v2", "docker://example.com/foo/bar"} {
 		m, err := c.FindMetadata(spec)
 		if err != nil {
@@ -156,6 +157,34 @@ func TestLocalActionsIgnoreRemoteActions(t *testing.T) {
 	}
 }
 
+func TestLocalActionsLogCacheHit(t *testing.T) {
+	dbg := &bytes.Buffer{}
+	proj := &Project{filepath.Join("testdata", "action_metadata"), nil}
+	c := NewLocalActionsCache(proj, dbg)
+
+	want := testGetWantedActionMetadata()
+	for i := 0; i < 2; i++ {
+		have, err := c.FindMetadata("./action-yml")
+		if err != nil {
+			t.Fatal(err)
+		}
+		if !cmp.Equal(want, have) {
+			t.Fatal(cmp.Diff(want, have))
+		}
+	}
+
+	logs := strings.Split(strings.TrimSpace(dbg.String()), "\n")
+	if len(logs) != 2 {
+		t.Fatalf("2 logs were expected but got %d logs: %#v", len(logs), logs)
+	}
+	if !strings.Contains(logs[0], "New metadata parsed from action "+filepath.Join("testdata", "action_metadata", "action-yml")) {
+		t.Fatalf("first log should be 'new metadata' but got %q", logs[0])
+	}
+	if !strings.Contains(logs[1], "Cache hit for ./action-yml") {
+		t.Fatalf("second log should be 'cache hit' but got %q", logs[1])
+	}
+}
+
 // Error cases
 
 func TestLocalActionsFailures(t *testing.T) {
@@ -180,7 +209,7 @@ func TestLocalActionsFailures(t *testing.T) {
 
 	for _, tc := range testCases {
 		t.Run(tc.what, func(t *testing.T) {
-			c := NewLocalActionsCache(proj)
+			c := NewLocalActionsCache(proj, nil)
 			m, err := c.FindMetadata(tc.spec)
 			if err == nil {
 				t.Fatal("error was not returned", m)
@@ -213,7 +242,7 @@ func TestLocalActionsFailures(t *testing.T) {
 func TestLocalActionsConcurrentFailures(t *testing.T) {
 	n := 10
 	proj := &Project{filepath.Join("testdata", "action_metadata"), nil}
-	c := NewLocalActionsCache(proj)
+	c := NewLocalActionsCache(proj, nil)
 	errC := make(chan error)
 
 	for i := 0; i < n; i++ {
@@ -247,7 +276,7 @@ func TestLocalActionsConcurrentFailures(t *testing.T) {
 
 func TestLocalActionsConcurrentMultipleMetadataAndFailures(t *testing.T) {
 	proj := &Project{filepath.Join("testdata", "action_metadata"), nil}
-	c := NewLocalActionsCache(proj)
+	c := NewLocalActionsCache(proj, nil)
 
 	inputs := []string{
 		"./action-yml",

linter.go

@@ -168,6 +168,13 @@ func (l *Linter) debug(format string, args ...interface{}) {
 	fmt.Fprintf(l.logOut, format, args...)
 }
 
+func (l *Linter) debugWriter() io.Writer {
+	if l.logLevel < LogLevelDebug {
+		return nil
+	}
+	return l.logOut
+}
+
 // GenerateDefaultConfig generates default config file at ".github/actionlint.yaml" in project
 // which the given directory path belongs to.
 func (l *Linter) GenerateDefaultConfig(dir string) error {
@@ -252,7 +259,7 @@ func (l *Linter) LintFiles(filepaths []string, project *Project) ([]*Error, erro
 	}
 
 	proc := newConcurrentProcess(runtime.NumCPU())
-	localActions := NewLocalActionsCache(project)
+	localActions := NewLocalActionsCache(project, l.debugWriter())
 	sema := semaphore.NewWeighted(int64(runtime.NumCPU()))
 	ctx := context.Background()
 
@@ -345,7 +352,7 @@ func (l *Linter) LintFile(path string, project *Project) ([]*Error, error) {
 	}
 
 	proc := newConcurrentProcess(runtime.NumCPU())
-	localActions := NewLocalActionsCache(project)
+	localActions := NewLocalActionsCache(project, l.debugWriter())
 	errs, err := l.check(path, src, project, proc, localActions)
 	proc.wait()
 	if err != nil {
@@ -363,7 +370,7 @@ func (l *Linter) LintFile(path string, project *Project) ([]*Error, error) {
 // based on path parameter.
 func (l *Linter) Lint(path string, content []byte, project *Project) ([]*Error, error) {
 	proc := newConcurrentProcess(runtime.NumCPU())
-	localActions := NewLocalActionsCache(project)
+	localActions := NewLocalActionsCache(project, l.debugWriter())
 	errs, err := l.check(path, content, project, proc, localActions)
 	proc.wait()
 	if err != nil {
@@ -411,10 +418,7 @@ func (l *Linter) check(path string, content []byte, project *Project, proc *conc
 	}
 
 	if w != nil {
-		dbg := l.logOut
-		if l.logLevel < LogLevelDebug {
-			dbg = nil
-		}
+		dbg := l.debugWriter()
 
 		var labels []string
 		if cfg != nil {

rule_action.go

@@ -83,6 +83,7 @@ func (rule *RuleAction) checkRepoAction(spec string, exec *ExecAction) {
 
 	meta, ok := PopularActions[spec]
 	if !ok {
+		rule.debug("This action is not found in popular actions data set: %s", spec)
 		return
 	}