Repository: magefile/mage
Pull request #168 (2018-09-18 14:11:12)

Rely on GOCACHE rather than our own hashing mechanism
This is about 100ms slower than using our own hash, but it's a heck of a lot more accurate about detecting when we need to rebuild.


Patch:
diff --git a/mage/main.go b/mage/main.go
index 3226531..598cace 100644
--- a/mage/main.go
+++ b/mage/main.go
@@ -46,7 +46,7 @@ var initOutput = template.Must(template.New("").Parse(mageTpl))
 const mainfile = "mage_output_file.go"
 const initFile = "magefile.go"
 
-var debug = log.New(ioutil.Discard, "DEBUG: ", 0)
+var debug = log.New(ioutil.Discard, "DEBUG: ", log.Ltime|log.Lmicroseconds)
 
 // set by ldflags when you "mage build"
 var (
@@ -130,6 +130,11 @@ func ParseAndRun(stdout, stderr io.Writer, stdin io.Reader, args []string) int {
 			log.Println("Error:", err)
 			return 1
 		}
+		if err := removeContents(filepath.Join(inv.CacheDir, mainfileSubdir)); err != nil {
+			log.Println("Error:", err)
+			return 1
+		}
+
 		log.Println(inv.CacheDir, "cleaned")
 		return 0
 	case CompileStatic:
@@ -148,7 +153,7 @@ func Parse(stderr, stdout io.Writer, args []string) (inv Invocation, cmd Command
 	fs := flag.FlagSet{}
 	fs.SetOutput(stdout)
 	fs.BoolVar(&inv.Force, "f", false, "force recreation of compiled magefile")
-	fs.BoolVar(&inv.Debug, "debug", mg.Debug(), "turn on debug messages (implies -keep)")
+	fs.BoolVar(&inv.Debug, "debug", mg.Debug(), "turn on debug messages")
 	fs.BoolVar(&inv.Verbose, "v", mg.Verbose(), "show verbose output when running mage targets")
 	fs.BoolVar(&inv.List, "l", false, "list mage targets in this directory")
 	fs.BoolVar(&inv.Help, "h", false, "show this help")
@@ -184,7 +189,7 @@ Commands:
 Options:
   -d <string> 
           run magefiles in the given directory (default ".")
-  -debug  turn on debug messages (implies -keep)
+  -debug  turn on debug messages
   -h      show description of a target
   -f      force recreation of compiled magefile
   -keep   keep intermediate mage files around after running
@@ -234,7 +239,6 @@ Options:
 
 	if inv.Debug {
 		debug.SetOutput(stderr)
-		inv.Keep = true
 	}
 
 	inv.CacheDir = mg.CacheDir()
@@ -286,20 +290,32 @@ func Invoke(inv Invocation) int {
 	}
 	debug.Println("output exe is ", exePath)
 
-	_, err = os.Stat(exePath)
-	switch {
-	case err == nil:
-		if inv.Force {
-			debug.Println("ignoring existing executable")
-		} else {
-			debug.Println("Running existing exe")
-			return RunCompiled(inv, exePath)
+	useCache := false
+	if s, err := outputDebug(inv.GoCmd, "env", "GOCACHE"); err == nil {
+		// if GOCACHE exists, always rebuild, so we catch transitive
+		// dependencies that have changed.
+		if s != "" {
+			debug.Println("build cache exists, will ignore any compiled binary")
+			useCache = true
+		}
+	}
+
+	if !useCache {
+		_, err = os.Stat(exePath)
+		switch {
+		case err == nil:
+			if inv.Force {
+				debug.Println("ignoring existing executable")
+			} else {
+				debug.Println("Running existing exe")
+				return RunCompiled(inv, exePath)
+			}
+		case os.IsNotExist(err):
+			debug.Println("no existing exe, creating new")
+		default:
+			debug.Printf("error reading existing exe at %v: %v", exePath, err)
+			debug.Println("creating new exe")
 		}
-	case os.IsNotExist(err):
-		debug.Println("no existing exe, creating new")
-	default:
-		debug.Printf("error reading existing exe at %v: %v", exePath, err)
-		debug.Println("creating new exe")
 	}
 
 	// parse wants dir + filenames... arg
@@ -318,17 +334,13 @@ func Invoke(inv Invocation) int {
 	}
 
 	main := filepath.Join(inv.Dir, mainfile)
-	if err := GenerateMainfile(main, info); err != nil {
+	mainhash, err := GenerateMainfile(main, inv.CacheDir, info)
+	if err != nil {
 		log.Println("Error:", err)
 		return 1
 	}
 	if !inv.Keep {
-		defer func() {
-			debug.Println("removing main file")
-			if err := os.Remove(main); err != nil && !os.IsNotExist(err) {
-				debug.Println("error removing main file: ", err)
-			}
-		}()
+		defer moveMainToCache(inv.CacheDir, main, mainhash)
 	}
 	files = append(files, main)
 	if err := Compile(inv.Dir, inv.GoCmd, exePath, files, inv.Debug, inv.Stderr, inv.Stdout); err != nil {
@@ -336,12 +348,10 @@ func Invoke(inv Invocation) int {
 		return 1
 	}
 	if !inv.Keep {
-		// remove this file before we run the compiled version, in case the
+		// move aside this file before we run the compiled version, in case the
 		// compiled file screws things up.  Yes this doubles up with the above
 		// defer, that's ok.
-		if err := os.Remove(main); err != nil && !os.IsNotExist(err) {
-			debug.Println("error removing main file: ", err)
-		}
+		moveMainToCache(inv.CacheDir, main, mainhash)
 	} else {
 		debug.Print("keeping mainfile")
 	}
@@ -353,6 +363,13 @@ func Invoke(inv Invocation) int {
 	return RunCompiled(inv, exePath)
 }
 
+func moveMainToCache(cachedir, main, hash string) {
+	debug.Println("moving main file to cache:", cachedMainfile(cachedir, hash))
+	if err := os.Rename(main, cachedMainfile(cachedir, hash)); err != nil && !os.IsNotExist(err) {
+		debug.Println("error caching main file: ", err)
+	}
+}
+
 type data struct {
 	Description  string
 	Funcs        []parse.Function
@@ -378,6 +395,10 @@ func goVersion(gocmd string) (string, error) {
 
 // Magefiles returns the list of magefiles in dir.
 func Magefiles(magePath, goCmd string, stderr io.Writer, isDebug bool) ([]string, error) {
+	start := time.Now()
+	defer func() {
+		debug.Println("time to scan for Magefiles:", time.Since(start))
+	}()
 	fail := func(err error) ([]string, error) {
 		return nil, err
 	}
@@ -441,23 +462,22 @@ func Compile(magePath, goCmd, compileTo string, gofiles []string, isDebug bool,
 	for i := range gofiles {
 		gofiles[i] = filepath.Base(gofiles[i])
 	}
-	debug.Printf("running %s build -o %s %s", goCmd, compileTo, strings.Join(gofiles, ", "))
+	debug.Printf("running %s build -o %s %s", goCmd, compileTo, strings.Join(gofiles, " "))
 	c := exec.Command(goCmd, append([]string{"build", "-o", compileTo}, gofiles...)...)
 	c.Env = os.Environ()
 	c.Stderr = stderr
 	c.Stdout = stdout
 	c.Dir = magePath
+	start := time.Now()
 	err := c.Run()
+	debug.Println("time to compile Magefile:", time.Since(start))
 	if err != nil {
 		return errors.New("error compiling magefiles")
 	}
-	if _, err := os.Stat(compileTo); err != nil {
-		return errors.New("failed to find compiled magefile")
-	}
 	return nil
 }
 
-func runDebug(cmd string, args ...string) {
+func runDebug(cmd string, args ...string) error {
 	buf := &bytes.Buffer{}
 	errbuf := &bytes.Buffer{}
 	debug.Println("running", cmd, strings.Join(args, " "))
@@ -467,18 +487,45 @@ func runDebug(cmd string, args ...string) {
 	c.Stdout = buf
 	if err := c.Run(); err != nil {
 		debug.Print("error running '", cmd, strings.Join(args, " "), "': ", err, ": ", errbuf)
+		return err
 	}
 	debug.Println(buf)
+	return nil
 }
 
-// GenerateMainfile creates the mainfile at path with the info from
-func GenerateMainfile(path string, info *parse.PkgInfo) error {
+func outputDebug(cmd string, args ...string) (string, error) {
+	buf := &bytes.Buffer{}
+	errbuf := &bytes.Buffer{}
+	debug.Println("running", cmd, strings.Join(args, " "))
+	c := exec.Command(cmd, args...)
+	c.Env = os.Environ()
+	c.Stderr = errbuf
+	c.Stdout = buf
+	if err := c.Run(); err != nil {
+		debug.Print("error running '", cmd, strings.Join(args, " "), "': ", err, ": ", errbuf)
+		return "", err
+	}
+	return strings.TrimSpace(buf.String()), nil
+}
+
+const mainfileSubdir = "mainfiles"
+
+func cachedMainfile(cachedir, hash string) string {
+	return filepath.Join(cachedir, mainfileSubdir, hash)
+}
+
+// GenerateMainfile generates the mage mainfile at path.  Because go build's
+// cache cares about modtimes, we squirrel away our mainfiles in the cachedir
+// and move them back as needed.
+func GenerateMainfile(path, cachedir string, info *parse.PkgInfo) (hash string, _ error) {
 	debug.Println("Creating mainfile at", path)
-	f, err := os.Create(path)
-	if err != nil {
-		return fmt.Errorf("can't create mainfile: %v", err)
+	mainfiles := filepath.Join(cachedir, mainfileSubdir)
+	if err := os.MkdirAll(mainfiles, 0700); err != nil {
+		return "", fmt.Errorf("failed to create path for mainfiles at %s: %v", mainfiles, err)
 	}
-	defer f.Close()
+	buf := &bytes.Buffer{}
+	hasher := sha1.New()
+	w := io.MultiWriter(buf, hasher)
 
 	data := data{
 		Description: info.Description,
@@ -490,10 +537,63 @@ func GenerateMainfile(path string, info *parse.PkgInfo) error {
 
 	data.DefaultError = info.DefaultIsError
 
-	if err := output.Execute(f, data); err != nil {
-		return fmt.Errorf("can't execute mainfile template: %v", err)
+	if err := output.Execute(w, data); err != nil {
+		return "", fmt.Errorf("can't execute mainfile template: %v", err)
 	}
-	return nil
+
+	hash = fmt.Sprintf("%x", hasher.Sum(nil))
+	cachedMain := filepath.Join(mainfiles, hash)
+	if useExistingMain(cachedMain, path, hash) {
+		info, err := os.Stat(path)
+		if err != nil {
+			debug.Println("mainfile modtime:", info.ModTime())
+		}
+		return hash, nil
+	}
+	debug.Println("writing new file at", path)
+	if err := ioutil.WriteFile(path, buf.Bytes(), 0600); err != nil {
+		return "", fmt.Errorf("can't write mainfile: %v", err)
+	}
+	return hash, nil
+}
+
+func useExistingMain(cachedMain, path, hash string) bool {
+	err := os.Rename(cachedMain, path)
+	if err == nil {
+		debug.Println("using cached mainfile from cachedir")
+		return true
+	}
+	if os.IsNotExist(err) {
+		debug.Println("file does not exist at", cachedMain)
+	} else {
+		debug.Printf("error copying cached mainfile from %s to %s: %v", cachedMain, path, err)
+	}
+	// ok, no cached file, try to open the file at the target (happens if
+	// the user ran with -keep)
+	f, err := os.Open(path)
+	if os.IsNotExist(err) {
+		return false
+	}
+	if err != nil {
+		debug.Printf("error opening existing mainfile at %s: %v", path, err)
+		return false
+	}
+	defer f.Close()
+	debug.Println("mainfile already exists at", path)
+	existing := sha1.New()
+	_, err = io.Copy(existing, f)
+	if err != nil {
+		debug.Println("error hashing existing file:", err)
+		return false
+	}
+
+	if hash == fmt.Sprintf("%x", existing.Sum(nil)) {
+		// same contents on disk, use those
+		debug.Println("mainfile is the same as generated, using existing file")
+		return true
+	}
+	debug.Println("existing file has different contents")
+	return false
 }
 
 // ExeName reports the executable filename that this version of Mage would
@@ -572,6 +672,9 @@ func RunCompiled(inv Invocation, exePath string) int {
 	if inv.Help {
 		c.Env = append(c.Env, "MAGEFILE_HELP=1")
 	}
+	if inv.Debug {
+		c.Env = append(c.Env, "MAGEFILE_DEBUG=1")
+	}
 	if inv.Timeout > 0 {
 		c.Env = append(c.Env, fmt.Sprintf("MAGEFILE_TIMEOUT=%s", inv.Timeout.String()))
 	}
diff --git a/mg/runtime.go b/mg/runtime.go
index 049ea44..0f6cbea 100644
--- a/mg/runtime.go
+++ b/mg/runtime.go
@@ -35,7 +35,7 @@ func Verbose() bool {
 
 // Debug reports whether a magefile was run with the verbose flag.
 func Debug() bool {
-	b, _ := strconv.ParseBool(os.Getenv(VerboseEnv))
+	b, _ := strconv.ParseBool(os.Getenv(DebugEnv))
 	return b
 }
 
diff --git a/parse/parse.go b/parse/parse.go
index a0a8b4a..643671e 100644
--- a/parse/parse.go
+++ b/parse/parse.go
@@ -11,9 +11,10 @@ import (
 	"log"
 	"os"
 	"strings"
+	"time"
 )
 
-var debug = log.New(ioutil.Discard, "DEBUG: ", 0)
+var debug = log.New(ioutil.Discard, "DEBUG: ", log.Ltime|log.Lmicroseconds)
 
 // EnableDebug turns on debug logging.
 func EnableDebug() {
@@ -95,6 +96,10 @@ func (f Function) TemplateString() string {
 
 // Package parses a package
 func Package(path string, files []string) (*PkgInfo, error) {
+	start := time.Now()
+	defer func() {
+		debug.Println("time parse Magefiles:", time.Since(start))
+	}()
 	fset := token.NewFileSet()
 	pkg, err := getPackage(path, files, fset)
 	if err != nil {
diff --git a/site/content/index.md b/site/content/index.md
index aad1afb..750214a 100644
--- a/site/content/index.md
+++ b/site/content/index.md
@@ -67,7 +67,7 @@ Commands:
 Options:
   -d <string> 
           run magefiles in the given directory (default ".")
-  -debug  turn on debug messages (implies -keep)
+  -debug  turn on debug messages
   -h      show description of a target
   -f      force recreation of compiled magefile
   -keep   keep intermediate mage files around after running


Test patch:
diff --git a/mage/main_test.go b/mage/main_test.go
index 8b1eb36..9ae47d4 100644
--- a/mage/main_test.go
+++ b/mage/main_test.go
@@ -44,10 +44,66 @@ func testmain(m *testing.M) int {
 	if err := os.Setenv(mg.CacheEnv, dir); err != nil {
 		log.Fatal(err)
 	}
-	defer os.Unsetenv(mg.CacheEnv)
+	if err := os.Unsetenv(mg.VerboseEnv); err != nil {
+		log.Fatal(err)
+	}
+	if err := os.Unsetenv(mg.DebugEnv); err != nil {
+		log.Fatal(err)
+	}
+	if err := os.Unsetenv(mg.IgnoreDefaultEnv); err != nil {
+		log.Fatal(err)
+	}
 	return m.Run()
 }
 
+func TestTransitiveDepCache(t *testing.T) {
+	cache, err := outputDebug("go", "env", "gocache")
+	if err != nil {
+		t.Fatal(err)
+	}
+	if cache == "" {
+		t.Skip("skipping gocache tests on go version without cache")
+	}
+	// Test that if we change a transitive dep, that we recompile
+	stdout := &bytes.Buffer{}
+	stderr := &bytes.Buffer{}
+	inv := Invocation{
+		Stderr: stderr,
+		Stdout: stdout,
+		Dir:    "testdata/transitiveDeps",
+		Args:   []string{"Run"},
+	}
+	code := Invoke(inv)
+	if code != 0 {
+		t.Fatalf("got code %v, err: %s", code, stderr)
+	}
+	expected := "woof\n"
+	if actual := stdout.String(); actual != expected {
+		t.Fatalf("expected %q but got %q", expected, actual)
+	}
+	// ok, so baseline, the generated and cached binary should do "woof"
+	// now change out the transitive dependency that does the output
+	// so that it produces different output.
+	if err := os.Rename("testdata/transitiveDeps/dep/dog.go", "testdata/transitiveDeps/dep/dog.notgo"); err != nil {
+		t.Fatal(err)
+	}
+	defer os.Rename("testdata/transitiveDeps/dep/dog.notgo", "testdata/transitiveDeps/dep/dog.go")
+	if err := os.Rename("testdata/transitiveDeps/dep/cat.notgo", "testdata/transitiveDeps/dep/cat.go"); err != nil {
+		t.Fatal(err)
+	}
+	defer os.Rename("testdata/transitiveDeps/dep/cat.go", "testdata/transitiveDeps/dep/cat.notgo")
+	stderr.Reset()
+	stdout.Reset()
+	code = Invoke(inv)
+	if code != 0 {
+		t.Fatalf("got code %v, err: %s", code, stderr)
+	}
+	expected = "meow\n"
+	if actual := stdout.String(); actual != expected {
+		t.Fatalf("expected %q but got %q", expected, actual)
+	}
+}
+
 func TestListMagefilesMain(t *testing.T) {
 	buf := &bytes.Buffer{}
 	files, err := Magefiles("testdata/mixed_main_files", "go", buf, false)
@@ -708,18 +764,33 @@ func TestClean(t *testing.T) {
 	if cmd != Clean {
 		t.Errorf("Expected 'clean' command but got %v", cmd)
 	}
-	code = ParseAndRun(ioutil.Discard, ioutil.Discard, &bytes.Buffer{}, []string{"-clean"})
+	buf := &bytes.Buffer{}
+	code = ParseAndRun(ioutil.Discard, buf, &bytes.Buffer{}, []string{"-clean"})
 	if code != 0 {
-		t.Errorf("expected 0, but got %v", code)
+		t.Fatalf("expected 0, but got %v: %s", code, buf)
 	}
 
-	files, err = ioutil.ReadDir(mg.CacheDir())
+	infos, err := ioutil.ReadDir(mg.CacheDir())
 	if err != nil {
-		t.Error("issue reading file:", err)
+		t.Fatal(err)
+	}
+
+	var names []string
+	for _, i := range infos {
+		if !i.IsDir() {
+			names = append(names, i.Name())
+		}
 	}
 
-	if len(files) != 0 {
-		t.Errorf("expected '-clean' to remove files from CACHE_DIR, but still have %v", files)
+	if len(names) != 0 {
+		t.Errorf("expected '-clean' to remove files from CACHE_DIR, but still have %v", names)
+	}
+	infos, err = ioutil.ReadDir(filepath.Join(mg.CacheDir(), mainfileSubdir))
+	if err != nil {
+		t.Error("issue reading directory:", err)
+	}
+	if len(infos) > 0 {
+		t.Fatalf("%d files left in mainfile subdir", len(infos))
 	}
 }
 
diff --git a/mage/testdata/transitiveDeps/dep/cat.notgo b/mage/testdata/transitiveDeps/dep/cat.notgo
new file mode 100644
index 0000000..bbb9379
--- /dev/null
+++ b/mage/testdata/transitiveDeps/dep/cat.notgo
@@ -0,0 +1,7 @@
+package dep
+
+import "fmt"
+
+func Speak() {
+    fmt.Println("meow")
+}
\ No newline at end of file
diff --git a/mage/testdata/transitiveDeps/dep/dog.go b/mage/testdata/transitiveDeps/dep/dog.go
new file mode 100644
index 0000000..1b2c2d6
--- /dev/null
+++ b/mage/testdata/transitiveDeps/dep/dog.go
@@ -0,0 +1,7 @@
+package dep
+
+import "fmt"
+
+func Speak() {
+	fmt.Println("woof")
+}
diff --git a/mage/testdata/transitiveDeps/magefile.go b/mage/testdata/transitiveDeps/magefile.go
new file mode 100644
index 0000000..60ebb48
--- /dev/null
+++ b/mage/testdata/transitiveDeps/magefile.go
@@ -0,0 +1,9 @@
+//+build mage
+
+package main
+
+import "./dep"
+
+func Run() {
+	dep.Speak()
+}