From 0fb96a3b74772971031e4a2ddb78853482133f6a Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Fabian=20St=C3=A4ber?= Date: Sun, 3 Mar 2019 10:46:00 +0100 Subject: [PATCH] #5 debugging failed test on appveyor.com (Windows) --- tailer/fswatcher/fswatcher.go | 3 + tailer/fswatcher_test.go | 100 +++++++++++++++++++++++++++------- 2 files changed, 84 insertions(+), 19 deletions(-) diff --git a/tailer/fswatcher/fswatcher.go b/tailer/fswatcher/fswatcher.go index ef86d161..2606286a 100644 --- a/tailer/fswatcher/fswatcher.go +++ b/tailer/fswatcher/fswatcher.go @@ -86,6 +86,9 @@ func (t *fileTailer) Errors() chan Error { return t.errors } +// Close() triggers the shutdown of the file tailer. +// The file tailer will eventually terminate, +// but after Close() returns it might still be running in the background for a few milliseconds. func (t *fileTailer) Close() { // Closing the done channel will stop the consumer loop. // Deferred functions within the consumer loop will close the producer loop. diff --git a/tailer/fswatcher_test.go b/tailer/fswatcher_test.go index 3ae276ba..7adb38ad 100644 --- a/tailer/fswatcher_test.go +++ b/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"}, @@ -156,21 +160,24 @@ func runTest(t *testing.T, ctx *context, cmds [][]string) { } func closeTailer(t *testing.T, ctx *context) { + // Note: This function checks if the Lines() channel gets closed. + // While it's good to check this, it doesn't guarantee that the tailer is + // fully shut down. There might be an fseventProducerLoop running in the + // background, or a hanging system call keeping the log directory open. + // There are tests for that like counting the number of goroutines + // in assertGoroutinesTerminated() or making sure the log directory + // can be removed in tearDown(). timeout := 5 * time.Second if ctx.tailer != nil { ctx.tailer.Close() - // wait until closed + // check if the lines channel gets closed 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 +475,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,9 +730,64 @@ 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, "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) { + // repeat a few times in case the file or directory is still used by the file system watcher. + var ( + err error + timeout = 5 * time.Second + timePassed = 0 * time.Second + ) + for timePassed < timeout { + err = os.Remove(file) + if err == nil { + // Check if the file or directory is really removed. On Windows, os.Remove() sometimes + // returns no error when removing the log directory, but the directory is still there. + _, 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 + } 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: %q: failed to remove file or directory: %v", file, err) + } else { + fatalf(t, ctx, "tearDown: %q: failed to remove file or directory", file) } } @@ -803,18 +865,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) }