watch: fix spurious errors while watching (docker#1726)

Author: nicks

pkg/watch/notify_test.go

@@ -1,6 +1,8 @@
 package watch
 
 import (
+	"bytes"
+	"context"
 	"fmt"
 	"io/ioutil"
 	"os"
@@ -10,6 +12,8 @@ import (
 	"testing"
 	"time"
 
+	"github.com/stretchr/testify/assert"
+	"github.com/windmilleng/tilt/internal/logger"
 	"github.com/windmilleng/tilt/internal/testutils/tempdir"
 )
 
@@ -54,6 +58,65 @@ func TestEventOrdering(t *testing.T) {
 	f.assertEvents(expected...)
 }
 
+// Simulate a git branch switch that creates a bunch
+// of directories, creates files in them, then deletes
+// them all quickly. Make sure there are no errors.
+func TestGitBranchSwitch(t *testing.T) {
+	f := newNotifyFixture(t)
+	defer f.tearDown()
+
+	count := 10
+	dirs := make([]string, count)
+	for i, _ := range dirs {
+		dir := f.TempDir("watched")
+		dirs[i] = dir
+		err := f.notify.Add(dir)
+		if err != nil {
+			t.Fatal(err)
+		}
+	}
+
+	f.fsync()
+	f.events = nil
+
+	// consume all the events in the background
+	ctx, cancel := context.WithCancel(context.Background())
+	done := f.consumeEventsInBackground(ctx)
+
+	for i, dir := range dirs {
+		for j := 0; j < count; j++ {
+			base := fmt.Sprintf("x/y/dir-%d/x.txt", j)
+			p := filepath.Join(dir, base)
+			f.WriteFile(p, "contents")
+		}
+
+		if i != 0 {
+			os.RemoveAll(dir)
+		}
+	}
+
+	cancel()
+	err := <-done
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	f.fsync()
+	f.events = nil
+
+	// Make sure the watch on the first dir still works.
+	dir := dirs[0]
+	path := filepath.Join(dir, "change")
+
+	f.WriteFile(path, "hello\n")
+	f.fsync()
+
+	f.assertEvents(path)
+
+	// Make sure there are no errors in the out stream
+	assert.Equal(t, "", f.out.String())
+}
+
 func TestWatchesAreRecursive(t *testing.T) {
 	f := newNotifyFixture(t)
 	defer f.tearDown()
@@ -412,14 +475,16 @@ func TestWatchNonexistentDirectory(t *testing.T) {
 // }
 
 type notifyFixture struct {
+	out *bytes.Buffer
 	*tempdir.TempDirFixture
 	notify  Notify
 	watched string
 	events  []FileEvent
 }
 
 func newNotifyFixture(t *testing.T) *notifyFixture {
-	notify, err := NewWatcher()
+	out := bytes.NewBuffer(nil)
+	notify, err := NewWatcher(logger.NewLogger(logger.DebugLvl, out))
 	if err != nil {
 		t.Fatal(err)
 	}
@@ -435,6 +500,7 @@ func newNotifyFixture(t *testing.T) *notifyFixture {
 		TempDirFixture: f,
 		watched:        watched,
 		notify:         notify,
+		out:            out,
 	}
 }
 
@@ -460,6 +526,25 @@ func (f *notifyFixture) assertEvents(expected ...string) {
 	}
 }
 
+func (f *notifyFixture) consumeEventsInBackground(ctx context.Context) chan error {
+	done := make(chan error)
+	go func() {
+		for {
+			select {
+			case <-ctx.Done():
+				close(done)
+				return
+			case err := <-f.notify.Errors():
+				done <- err
+				close(done)
+				return
+			case <-f.notify.Events():
+			}
+		}
+	}()
+	return done
+}
+
 func (f *notifyFixture) fsync() {
 	syncPathBase := fmt.Sprintf("sync-%d.txt", time.Now().UnixNano())
 	syncPath := filepath.Join(f.watched, syncPathBase)

pkg/watch/watcher_darwin.go

@@ -5,6 +5,7 @@ import (
 	"sync"
 	"time"
 
+	"github.com/windmilleng/tilt/internal/logger"
 	"github.com/windmilleng/tilt/internal/ospath"
 
 	"github.com/windmilleng/fsevents"
@@ -120,7 +121,7 @@ func (d *darwinNotify) Errors() chan error {
 	return d.errors
 }
 
-func NewWatcher() (Notify, error) {
+func NewWatcher(l logger.Logger) (Notify, error) {
 	dw := &darwinNotify{
 		stream: &fsevents.EventStream{
 			Latency: 1 * time.Millisecond,

pkg/watch/watcher_naive.go

@@ -4,14 +4,14 @@ package watch
 
 import (
 	"fmt"
-	"log"
 	"os"
 	"path/filepath"
 	"sync"
 
 	"github.com/pkg/errors"
 	"github.com/windmilleng/fsnotify"
 
+	"github.com/windmilleng/tilt/internal/logger"
 	"github.com/windmilleng/tilt/internal/ospath"
 )
 
@@ -20,6 +20,7 @@ import (
 //
 // All OS-specific codepaths are handled by fsnotify.
 type naiveNotify struct {
+	log           logger.Logger
 	watcher       *fsnotify.Watcher
 	events        chan fsnotify.Event
 	wrappedEvents chan FileEvent
@@ -127,7 +128,7 @@ func (d *naiveNotify) loop() {
 		}
 
 		// TODO(dbentley): if there's a delete should we call d.watcher.Remove to prevent leaking?
-		if err := filepath.Walk(e.Name, func(path string, mode os.FileInfo, err error) error {
+		err := filepath.Walk(e.Name, func(path string, mode os.FileInfo, err error) error {
 			if err != nil {
 				return err
 			}
@@ -151,13 +152,14 @@ func (d *naiveNotify) loop() {
 			}
 			if shouldWatch {
 				err := d.watcher.Add(path)
-				if err != nil {
-					log.Printf("Error watching path %s: %s", e.Name, err)
+				if err != nil && !os.IsNotExist(err) {
+					d.log.Infof("Error watching path %s: %s", e.Name, err)
 				}
 			}
 			return nil
-		}); err != nil {
-			log.Printf("Error walking directory %s: %s", e.Name, err)
+		})
+		if err != nil && !os.IsNotExist(err) {
+			d.log.Infof("Error walking directory %s: %s", e.Name, err)
 		}
 	}
 }
@@ -177,7 +179,7 @@ func (d *naiveNotify) shouldNotify(path string) bool {
 	return false
 }
 
-func NewWatcher() (*naiveNotify, error) {
+func NewWatcher(l logger.Logger) (*naiveNotify, error) {
 	fsw, err := fsnotify.NewWatcher()
 	if err != nil {
 		return nil, err
@@ -186,6 +188,7 @@ func NewWatcher() (*naiveNotify, error) {
 	wrappedEvents := make(chan FileEvent)
 
 	wmw := &naiveNotify{
+		log:           l,
 		watcher:       fsw,
 		events:        fsw.Events,
 		wrappedEvents: wrappedEvents,