Skip to content

Commit

Permalink
Add debug log and unit test for fsnotify remove and rename (ansible#1208
Browse files Browse the repository at this point in the history 
)
  • Loading branch information
@matoval
matoval authored Nov 15, 2024
1 parent 3afac30 commit ded8059
Show file tree
Hide file tree
Showing 2 changed files with 78 additions and 23 deletions.
15 changes: 13 additions & 2 deletions pkg/workceptor/workunitbase.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -432,13 +432,24 @@ loop:
case <-bwu.ctx.Done():
break loop
case event := <-watcherEvents:
if event.Has(fsnotify.Create) {
switch {
case event.Has(fsnotify.Create):
bwu.w.nc.GetLogger().Debug("Watcher Event create of %s", statusFile)
} else if event.Op&fsnotify.Write == fsnotify.Write {
case event.Op&fsnotify.Write == fsnotify.Write:
err = bwu.Load()
if err != nil {
bwu.w.nc.GetLogger().Error("Watcher Events Error reading %s: %s", statusFile, err)
}
case event.Op&fsnotify.Remove == fsnotify.Remove:
err = bwu.Load()
if err != nil {
bwu.w.nc.GetLogger().Debug("Watcher Events Remove reading %s: %s", statusFile, err)
}
case event.Op&fsnotify.Rename == fsnotify.Rename:
err = bwu.Load()
if err != nil {
bwu.w.nc.GetLogger().Debug("Watcher Events Rename reading %s: %s", statusFile, err)
}
}
case <-time.After(time.Second):
newFi, err := bwu.fs.Stat(statusFile)
Expand Down
86 changes: 65 additions & 21 deletions pkg/workceptor/workunitbase_test.go
View file
Original file line number Diff line number Diff line change
@@ -1,15 +1,18 @@
package workceptor_test

import (
"bytes"
"context"
"errors"
"fmt"
"os"
"path"
"strings"
"testing"
"time"

"github.com/ansible/receptor/pkg/logger"
"github.com/ansible/receptor/pkg/randstr"
"github.com/ansible/receptor/pkg/workceptor"
"github.com/ansible/receptor/pkg/workceptor/mock_workceptor"
"github.com/fsnotify/fsnotify"
Expand Down Expand Up @@ -81,12 +84,13 @@ func TestIsPending(t *testing.T) {
}
}

func setUp(t *testing.T) (*gomock.Controller, workceptor.BaseWorkUnit, *workceptor.Workceptor, *mock_workceptor.MockNetceptorForWorkceptor) {
func setUp(t *testing.T) (*gomock.Controller, workceptor.BaseWorkUnit, *workceptor.Workceptor, *mock_workceptor.MockNetceptorForWorkceptor, *logger.ReceptorLogger) {
ctrl := gomock.NewController(t)

mockNetceptor := mock_workceptor.NewMockNetceptorForWorkceptor(ctrl)

// attach logger to the mock netceptor and return any number of times
logger.SetGlobalLogLevel(4)
logger := logger.NewReceptorLogger("")
mockNetceptor.EXPECT().GetLogger().AnyTimes().Return(logger)
mockNetceptor.EXPECT().NodeID().Return("NodeID")
Expand All @@ -98,45 +102,45 @@ func setUp(t *testing.T) (*gomock.Controller, workceptor.BaseWorkUnit, *workcept

bwu := workceptor.BaseWorkUnit{}

return ctrl, bwu, w, mockNetceptor
return ctrl, bwu, w, mockNetceptor, logger
}

func TestInit(t *testing.T) {
ctrl, bwu, w, _ := setUp(t)
ctrl, bwu, w, _, _ := setUp(t)
bwu.Init(w, "test", "test", workceptor.FileSystem{}, nil)
ctrl.Finish()
}

func TestErrorLog(t *testing.T) {
ctrl, bwu, w, _ := setUp(t)
ctrl, bwu, w, _, _ := setUp(t)
bwu.Init(w, "test", "test", workceptor.FileSystem{}, &workceptor.RealWatcher{})
bwu.Error("test error")
ctrl.Finish()
}

func TestWarningLog(t *testing.T) {
ctrl, bwu, w, _ := setUp(t)
ctrl, bwu, w, _, _ := setUp(t)
bwu.Init(w, "test", "test", workceptor.FileSystem{}, &workceptor.RealWatcher{})
bwu.Warning("test warning")
ctrl.Finish()
}

func TestInfoLog(t *testing.T) {
ctrl, bwu, w, _ := setUp(t)
ctrl, bwu, w, _, _ := setUp(t)
bwu.Init(w, "test", "test", workceptor.FileSystem{}, &workceptor.RealWatcher{})
bwu.Info("test info")
ctrl.Finish()
}

func TestDebugLog(t *testing.T) {
ctrl, bwu, w, _ := setUp(t)
ctrl, bwu, w, _, _ := setUp(t)
bwu.Init(w, "test", "test", workceptor.FileSystem{}, &workceptor.RealWatcher{})
bwu.Error("test debug")
ctrl.Finish()
}

func TestSetFromParams(t *testing.T) {
ctrl, bwu, w, _ := setUp(t)
ctrl, bwu, w, _, _ := setUp(t)
bwu.Init(w, "test", "test", workceptor.FileSystem{}, &workceptor.RealWatcher{})
err := bwu.SetFromParams(nil)
if err != nil {
Expand All @@ -152,7 +156,7 @@ const (
)

func TestUnitDir(t *testing.T) {
ctrl, bwu, w, _ := setUp(t)
ctrl, bwu, w, _, _ := setUp(t)
bwu.Init(w, "test", "test", workceptor.FileSystem{}, &workceptor.RealWatcher{})
expectedUnitDir := path.Join(rootDir, testDir)
if unitDir := bwu.UnitDir(); unitDir != expectedUnitDir {
Expand All @@ -162,7 +166,7 @@ func TestUnitDir(t *testing.T) {
}

func TestID(t *testing.T) {
ctrl, bwu, w, _ := setUp(t)
ctrl, bwu, w, _, _ := setUp(t)
bwu.Init(w, "test", "test", workceptor.FileSystem{}, &workceptor.RealWatcher{})
if id := bwu.ID(); id != "test" {
t.Errorf("ID returned wrong value: got %s, want %s", id, "test")
Expand All @@ -171,7 +175,7 @@ func TestID(t *testing.T) {
}

func TestStatusFileName(t *testing.T) {
ctrl, bwu, w, _ := setUp(t)
ctrl, bwu, w, _, _ := setUp(t)
bwu.Init(w, "test", "", workceptor.FileSystem{}, &workceptor.RealWatcher{})
expectedUnitDir := path.Join(rootDir, testDir)
expectedStatusFileName := path.Join(expectedUnitDir, "status")
Expand All @@ -182,7 +186,7 @@ func TestStatusFileName(t *testing.T) {
}

func TestStdoutFileName(t *testing.T) {
ctrl, bwu, w, _ := setUp(t)
ctrl, bwu, w, _, _ := setUp(t)
bwu.Init(w, "test", "", workceptor.FileSystem{}, &workceptor.RealWatcher{})
expectedUnitDir := path.Join(rootDir, testDir)
expectedStdoutFileName := path.Join(expectedUnitDir, "stdout")
Expand All @@ -193,7 +197,7 @@ func TestStdoutFileName(t *testing.T) {
}

func TestBaseSave(t *testing.T) {
ctrl, bwu, w, _ := setUp(t)
ctrl, bwu, w, _, _ := setUp(t)
bwu.Init(w, "test", "", workceptor.FileSystem{}, &workceptor.RealWatcher{})
err := bwu.Save()
if !strings.Contains(err.Error(), dirError) {
Expand All @@ -203,7 +207,7 @@ func TestBaseSave(t *testing.T) {
}

func TestBaseLoad(t *testing.T) {
ctrl, bwu, w, _ := setUp(t)
ctrl, bwu, w, _, _ := setUp(t)
bwu.Init(w, "test", "", workceptor.FileSystem{}, &workceptor.RealWatcher{})
err := bwu.Load()
if !strings.Contains(err.Error(), dirError) {
Expand All @@ -213,7 +217,7 @@ func TestBaseLoad(t *testing.T) {
}

func TestBaseUpdateFullStatus(t *testing.T) {
ctrl, bwu, w, _ := setUp(t)
ctrl, bwu, w, _, _ := setUp(t)
bwu.Init(w, "test", "", workceptor.FileSystem{}, &workceptor.RealWatcher{})
sf := func(sfd *workceptor.StatusFileData) {
// Do nothing
Expand All @@ -227,7 +231,7 @@ func TestBaseUpdateFullStatus(t *testing.T) {
}

func TestBaseUpdateBasicStatus(t *testing.T) {
ctrl, bwu, w, _ := setUp(t)
ctrl, bwu, w, _, _ := setUp(t)
bwu.Init(w, "test", "", workceptor.FileSystem{}, &workceptor.RealWatcher{})
bwu.UpdateBasicStatus(1, "Details", 0)
err := bwu.LastUpdateError()
Expand All @@ -238,7 +242,7 @@ func TestBaseUpdateBasicStatus(t *testing.T) {
}

func TestBaseStatus(t *testing.T) {
ctrl, bwu, w, _ := setUp(t)
ctrl, bwu, w, _, _ := setUp(t)
bwu.Init(w, "test", "", workceptor.FileSystem{}, &workceptor.RealWatcher{})
status := bwu.Status()
if status.State != workceptor.WorkStatePending {
Expand All @@ -248,7 +252,7 @@ func TestBaseStatus(t *testing.T) {
}

func TestBaseRelease(t *testing.T) {
ctrl, bwu, w, _ := setUp(t)
ctrl, bwu, w, _, _ := setUp(t)
mockFileSystem := mock_workceptor.NewMockFileSystemer(ctrl)
bwu.Init(w, "test", "", mockFileSystem, &workceptor.RealWatcher{})

Expand Down Expand Up @@ -300,6 +304,7 @@ func TestMonitorLocalStatus(t *testing.T) {
addWatcherErr error
statErr error
fsNotifyEvent *fsnotify.Event // using pointer to allow nil
logOutput string
sleepDuration time.Duration
}{
{
Expand All @@ -308,6 +313,7 @@ func TestMonitorLocalStatus(t *testing.T) {
addWatcherErr: nil,
statErr: nil,
fsNotifyEvent: &fsnotify.Event{Op: fsnotify.Write},
logOutput: "Watcher Events Error reading",
sleepDuration: 100 * time.Millisecond,
},
{
Expand All @@ -316,6 +322,7 @@ func TestMonitorLocalStatus(t *testing.T) {
addWatcherErr: fmt.Errorf("error adding watcher"),
statErr: nil,
fsNotifyEvent: nil,
logOutput: "",
sleepDuration: 100 * time.Millisecond,
},
{
Expand All @@ -324,6 +331,7 @@ func TestMonitorLocalStatus(t *testing.T) {
addWatcherErr: fmt.Errorf("error adding watcher"),
statErr: fmt.Errorf("stat error"),
fsNotifyEvent: nil,
logOutput: "",
sleepDuration: 100 * time.Millisecond,
},
{
Expand All @@ -332,6 +340,7 @@ func TestMonitorLocalStatus(t *testing.T) {
addWatcherErr: nil,
statErr: nil,
fsNotifyEvent: &fsnotify.Event{Op: fsnotify.Write},
logOutput: "Watcher Events Error reading",
sleepDuration: 100 * time.Millisecond,
},
{
Expand All @@ -341,14 +350,35 @@ func TestMonitorLocalStatus(t *testing.T) {
addWatcherErr: nil,
statErr: nil,
fsNotifyEvent: &fsnotify.Event{Op: fsnotify.Write},
logOutput: "Watcher Events Error reading",
sleepDuration: 500 * time.Millisecond,
},
{
name: "Handle Remove Event",
statObj: NewInfo("test", 1, 0, time.Now()),
addWatcherErr: nil,
statErr: nil,
fsNotifyEvent: &fsnotify.Event{Op: fsnotify.Remove},
logOutput: "Watcher Events Remove reading",
sleepDuration: 100 * time.Millisecond,
},
{
name: "Handle Rename Event",
statObj: NewInfo("test", 1, 0, time.Now()),
addWatcherErr: nil,
statErr: nil,
fsNotifyEvent: &fsnotify.Event{Op: fsnotify.Rename},
logOutput: "Watcher Events Rename reading",
sleepDuration: 100 * time.Millisecond,
},
}

for _, tc := range tests {
t.Run(tc.name, func(t *testing.T) {
ctrl, bwu, w, _ := setUp(t)
ctrl, bwu, w, _, l := setUp(t)
defer ctrl.Finish()
randstring := randstr.RandomString(4)
logFilePath := fmt.Sprintf("/tmp/monitorLocalStatusLog%s", randstring)

mockWatcher := mock_workceptor.NewMockWatcherWrapper(ctrl)
mockFileSystem := mock_workceptor.NewMockFileSystemer(ctrl)
Expand All @@ -362,18 +392,32 @@ func TestMonitorLocalStatus(t *testing.T) {
mockWatcher.EXPECT().Close().AnyTimes()

if tc.fsNotifyEvent != nil {
logFile, err := os.OpenFile(logFilePath, os.O_WRONLY|os.O_CREATE|os.O_APPEND, 0o600)
if err != nil {
t.Error("error creating monitorLocalStatusLog file")
}
l.SetOutput(logFile)
eventCh := make(chan fsnotify.Event, 1)
mockWatcher.EXPECT().EventChannel().Return(eventCh).AnyTimes()
go func() { eventCh <- *tc.fsNotifyEvent }()

errorCh := make(chan error, 1)
mockWatcher.EXPECT().ErrorChannel().Return(errorCh).AnyTimes()
// go func() { errorCh <- nil }()
}

go bwu.MonitorLocalStatus()

time.Sleep(tc.sleepDuration)

if tc.fsNotifyEvent != nil {
logOutput, err := os.ReadFile(logFilePath)
if err != nil && len(logOutput) == 0 {
t.Errorf("error reading %s file", logFilePath)
}
if !bytes.Contains(logOutput, []byte(tc.logOutput)) {
t.Errorf("expected log to be: %s, got %s", tc.logOutput, string(logOutput))
}
}

bwu.CancelContext()
})
}
Expand Down

0 comments on commit ded8059

Please sign in to comment.