#5 debugging failed test on appveyor.com (Windows)

Author: fstab

tailer/fswatcher_test.go

@@ -95,26 +95,30 @@ func TestAll(t *testing.T) {
 // * directories with the xattr com.apple.FinderInfo (like everything in /tmp) are hidden
 // In order to test this, we must create a log file somewhere outside of /tmp, so we use $HOME.
 func TestVisibleInOSXFinder(t *testing.T) {
+	ctx := setUp(t, "visible in macOS finder", closeFileAfterEachLine, fseventTailer, _nocreate, mv)
+
+	// replace ctx.basedir with a directory in $HOME
 	currentUser, err := user.Current()
 	if err != nil {
-		t.Fatalf("failed to get current user: %v", err)
+		fatalf(t, ctx, "failed to get current user: %v", err)
 	}
 	testDir, err := ioutil.TempDir(currentUser.HomeDir, "grok_exporter_test_dir_")
 	if err != nil {
-		t.Fatalf("failed to create test directory: %v", err.Error())
+		fatalf(t, ctx, "failed to create test directory: %v", err.Error())
 	}
 	defer func() {
 		err := os.RemoveAll(testDir)
 		if err != nil {
-			t.Fatalf("%v: Failed to remove test directory after running the tests: %v", testDir, err.Error())
+			fatalf(t, ctx, "%v: Failed to remove test directory after running the tests: %v", testDir, err.Error())
 		}
 	}()
-	ctx := setUp(t, "visible in macOS finder", closeFileAfterEachLine, fseventTailer, _nocreate, mv)
 	err = os.RemoveAll(ctx.basedir)
 	if err != nil {
-		t.Fatalf("%v: failed to remove temp dir: %v", ctx.basedir, err)
+		fatalf(t, ctx, "%v: failed to remove temp dir: %v", ctx.basedir, err)
 	}
 	ctx.basedir = testDir
+
+	// run simple test in the new directory
 	test := [][]string{
 		{"log", "line 1", "test.log"},
 		{"start file tailer", "test.log"},
@@ -163,14 +167,10 @@ func closeTailer(t *testing.T, ctx *context) {
 		select {
 		case line, open := <-ctx.tailer.Lines():
 			if open {
-				msg := fmt.Sprintf("read unexpected line line from file %q: %q", line.File, line.Line)
-				ctx.log.Error(msg)
-				t.Fatal(msg)
+				fatalf(t, ctx, "read unexpected line line from file %q: %q", line.File, line.Line)
 			}
 		case <-time.After(timeout):
-			msg := fmt.Sprintf("failed to shut down the tailer. timeout after %v seconds", timeout)
-			ctx.log.Error(msg)
-			fatalf(t, ctx, msg)
+			fatalf(t, ctx, "failed to shut down the tailer. timeout after %v seconds", timeout)
 		}
 	}
 }
@@ -468,7 +468,7 @@ func startFileTailer(t *testing.T, ctx *context, params []string) {
 	for _, g := range globs {
 		parsedGlob, err := glob.Parse(filepath.Join(ctx.basedir, g))
 		if err != nil {
-			t.Fatal(err)
+			fatalf(t, ctx, "%v", err)
 		}
 		parsedGlobs = append(parsedGlobs, parsedGlob)
 	}
@@ -723,10 +723,59 @@ func (l *keepOpenLogFileWriter) close(t *testing.T, ctx *context) {
 }
 
 func tearDown(t *testing.T, ctx *context) {
-	err := os.RemoveAll(ctx.basedir)
+	deleteRecursively(t, ctx, ctx.basedir)
+}
+
+func deleteRecursively(t *testing.T, ctx *context, file string) {
+	// os.RemoveAll() fails on Windows with "Access is denied".
+	// Remove each file individually to learn which file cannot be removed.
+	fileInfo, err := os.Stat(file)
 	if err != nil {
-		fatalf(t, ctx, "%v: failed to remove the test directory after running the tests: %v", ctx.basedir, err)
+		fatalf(t, ctx, "tearDown: stat(%q) failed: %v", file, err)
+	}
+	if fileInfo.IsDir() {
+		for _, childInfo := range ls(t, ctx, file) {
+			deleteRecursively(t, ctx, path.Join(file, childInfo.Name()))
+		}
+	}
+	ctx.log.Debugf("tearDown: removing %q", file)
+	delete(t, ctx, file)
+	//if err != nil {
+	//	// We get "The directory is not empty" here on Windows.
+	//	// Let's print what files are in here.
+	//	var filesInDir []string
+	//	for _, fileInDir := range ls(t, ctx, file) {
+	//		filesInDir = append(filesInDir, fileInDir.Name())
+	//	}
+	//	fatalf(t, ctx, "tearDown: %q: remove failed: %v. number of files in dir: %v, list of file in dir: %#v", file, err, len(filesInDir), filesInDir)
+	//}
+}
+
+func delete(t *testing.T, ctx *context, file string) {
+	// os.Remove() seems to fail on Windows without returning an error (file or directory is still there after os.Remove()).
+	// Maybe it's a timing problem with the watcher still keeping the file or directory alive.
+	// This function checks if the file or directory was deleted and tries again if it is still there.
+	timeout := 5 * time.Second
+	timePassed := 0 * time.Second
+	for timePassed < timeout {
+		err := os.Remove(file)
+		if err != nil {
+			fatalf(t, ctx, "tearDown: %q: remove failed: %v", file, err)
+		}
+		_, err = os.Stat(file)
+		if err != nil {
+			if os.IsNotExist(err) {
+				// os.Remove(file) was successful, the file or directory is gone.
+				return
+			} else {
+				fatalf(t, ctx, "tearDown: %q: stat failed: %v", file, err)
+			}
+		}
+		// os.Stat() successful. The file or directory is still there. Try again.
+		time.Sleep(200 * time.Millisecond)
+		timePassed += 200 * time.Millisecond
 	}
+	fatalf(t, ctx, "tearDown: %q: failed to remove file or directory", file)
 }
 
 func printCmd(cmd []string) string {
@@ -803,18 +852,18 @@ func runTestShutdown(t *testing.T, mode string) {
 	select {
 	case _, open := <-tailer.Errors():
 		if open {
-			t.Fatalf("error channel not closed")
+			fatalf(t, ctx, "error channel not closed")
 		}
 	case <-time.After(5 * time.Second):
-		t.Fatalf("timeout while waiting for errors channel to be closed.")
+		fatalf(t, ctx, "timeout while waiting for errors channel to be closed.")
 	}
 	select {
 	case _, open := <-tailer.Lines():
 		if open {
-			t.Fatalf("lines channel not closed")
+			fatalf(t, ctx, "lines channel not closed")
 		}
 	case <-time.After(5 * time.Second):
-		t.Fatalf("timeout while waiting for errors channel to be closed.")
+		fatalf(t, ctx, "timeout while waiting for errors channel to be closed.")
 	}
 	assertGoroutinesTerminated(t, ctx, nGoroutinesBefore)
 }