package hooks_test import ( "bytes" "context" "fmt" "os" "regexp" "testing" "text/template" "github.com/stretchr/testify/require" "github.com/zrepl/zrepl/daemon/logging/trace" "github.com/zrepl/zrepl/config" "github.com/zrepl/zrepl/daemon/hooks" "github.com/zrepl/zrepl/daemon/logging" "github.com/zrepl/zrepl/logger" "github.com/zrepl/zrepl/zfs" ) type comparisonAssertionFunc func(require.TestingT, interface{}, interface{}, ...interface{}) type valueAssertionFunc func(require.TestingT, interface{}, ...interface{}) type expectStep struct { ExpectedEdge hooks.Edge ExpectStatus hooks.StepStatus OutputTest valueAssertionFunc ErrorTest valueAssertionFunc } type testCase struct { Name string Config []string IsSlow bool SuppressOutput bool ExpectCallbackSkipped bool ExpectHadFatalErr bool ExpectHadError bool ExpectStepReports []expectStep } func curryLeft(f comparisonAssertionFunc, expected interface{}) valueAssertionFunc { return curry(f, expected, false) } func curryRight(f comparisonAssertionFunc, expected interface{}) valueAssertionFunc { return curry(f, expected, true) } func curry(f comparisonAssertionFunc, expected interface{}, right bool) (ret valueAssertionFunc) { ret = func(t require.TestingT, s interface{}, v ...interface{}) { var x interface{} var y interface{} if right { x = s y = expected } else { x = expected y = s } if len(v) > 0 { f(t, x, y, v) } else { f(t, x, y) } } return } func TestHooks(t *testing.T) { ctx, end := trace.WithTaskFromStack(context.Background()) defer end() testFSName := "testpool/testdataset" testSnapshotName := "testsnap" tmpl, err := template.New("TestHooks").Parse(` jobs: - name: TestHooks type: snap filesystems: {"<": true} snapshotting: type: periodic interval: 1m prefix: zrepl_snapjob_ hooks: {{- template "List" . }} pruning: keep: - type: last_n count: 10 `) if err != nil { panic(err) } regexpTest := func(s string) valueAssertionFunc { return curryLeft(require.Regexp, regexp.MustCompile(s)) } containsTest := func(s string) valueAssertionFunc { return curryRight(require.Contains, s) } testTable := []testCase{ testCase{ Name: "no_hooks", ExpectStepReports: []expectStep{ {ExpectedEdge: hooks.Callback, ExpectStatus: hooks.StepOk}, }, }, testCase{ Name: "timeout", IsSlow: true, ExpectHadError: true, Config: []string{`{type: command, path: {{.WorkDir}}/test/test-timeout.sh, timeout: 2s}`}, ExpectStepReports: []expectStep{ expectStep{ ExpectedEdge: hooks.Pre, ExpectStatus: hooks.StepErr, OutputTest: containsTest(fmt.Sprintf("TEST pre_testing %s@%s ZREPL_TIMEOUT=2", testFSName, testSnapshotName)), ErrorTest: regexpTest(`timed out after 2(.\d+)?s`), }, expectStep{ExpectedEdge: hooks.Callback, ExpectStatus: hooks.StepOk}, expectStep{ ExpectedEdge: hooks.Post, ExpectStatus: hooks.StepSkippedDueToPreErr, }, }, }, testCase{ Name: "check_env", Config: []string{`{type: command, path: {{.WorkDir}}/test/test-report-env.sh}`}, ExpectHadError: false, ExpectStepReports: []expectStep{ expectStep{ ExpectedEdge: hooks.Pre, ExpectStatus: hooks.StepOk, OutputTest: containsTest(fmt.Sprintf("TEST pre_testing %s@%s", testFSName, testSnapshotName)), }, expectStep{ExpectedEdge: hooks.Callback, ExpectStatus: hooks.StepOk}, expectStep{ ExpectedEdge: hooks.Post, ExpectStatus: hooks.StepOk, OutputTest: containsTest(fmt.Sprintf("TEST post_testing %s@%s", testFSName, testSnapshotName)), }, }, }, testCase{ Name: "nonfatal_pre_error_continues", ExpectCallbackSkipped: false, ExpectHadError: true, Config: []string{`{type: command, path: {{.WorkDir}}/test/test-error.sh}`}, ExpectStepReports: []expectStep{ expectStep{ ExpectedEdge: hooks.Pre, ExpectStatus: hooks.StepErr, OutputTest: containsTest(fmt.Sprintf("TEST ERROR pre_testing %s@%s", testFSName, testSnapshotName)), ErrorTest: regexpTest("^command hook invocation.*exit status 1$"), }, expectStep{ExpectedEdge: hooks.Callback, ExpectStatus: hooks.StepOk}, expectStep{ ExpectedEdge: hooks.Post, ExpectStatus: hooks.StepSkippedDueToPreErr, // post-edge is not executed for failing pre-edge }, }, }, testCase{ Name: "pre_error_fatal_skips_subsequent_pre_edges_and_callback_and_its_post_edge_and_post_edges", ExpectCallbackSkipped: true, ExpectHadFatalErr: true, ExpectHadError: true, Config: []string{ `{type: command, path: {{.WorkDir}}/test/test-error.sh, err_is_fatal: true}`, `{type: command, path: {{.WorkDir}}/test/test-report-env.sh}`, }, ExpectStepReports: []expectStep{ expectStep{ ExpectedEdge: hooks.Pre, ExpectStatus: hooks.StepErr, OutputTest: containsTest(fmt.Sprintf("TEST ERROR pre_testing %s@%s", testFSName, testSnapshotName)), ErrorTest: regexpTest("^command hook invocation.*exit status 1$"), }, expectStep{ ExpectedEdge: hooks.Pre, ExpectStatus: hooks.StepSkippedDueToFatalErr, }, expectStep{ExpectedEdge: hooks.Callback, ExpectStatus: hooks.StepSkippedDueToFatalErr}, expectStep{ ExpectedEdge: hooks.Post, ExpectStatus: hooks.StepSkippedDueToFatalErr, }, expectStep{ ExpectedEdge: hooks.Post, ExpectStatus: hooks.StepSkippedDueToFatalErr, }, }, }, testCase{ Name: "post_error_fails_are_ignored_even_if_fatal", ExpectHadFatalErr: false, // only occurs during Post, so it's not a fatal error ExpectHadError: true, Config: []string{ `{type: command, path: {{.WorkDir}}/test/test-post-error.sh, err_is_fatal: true}`, `{type: command, path: {{.WorkDir}}/test/test-report-env.sh}`, }, ExpectStepReports: []expectStep{ expectStep{ // No-action run of test-post-error.sh ExpectedEdge: hooks.Pre, ExpectStatus: hooks.StepOk, OutputTest: require.Empty, }, expectStep{ // Pre run of test-report-env.sh ExpectedEdge: hooks.Pre, ExpectStatus: hooks.StepOk, OutputTest: containsTest(fmt.Sprintf("TEST pre_testing %s@%s", testFSName, testSnapshotName)), }, expectStep{ExpectedEdge: hooks.Callback, ExpectStatus: hooks.StepOk}, expectStep{ ExpectedEdge: hooks.Post, ExpectStatus: hooks.StepOk, OutputTest: containsTest(fmt.Sprintf("TEST post_testing %s@%s", testFSName, testSnapshotName)), }, expectStep{ ExpectedEdge: hooks.Post, ExpectStatus: hooks.StepErr, OutputTest: containsTest(fmt.Sprintf("TEST ERROR post_testing %s@%s", testFSName, testSnapshotName)), ErrorTest: regexpTest("^command hook invocation.*exit status 1$"), }, }, }, testCase{ Name: "cleanup_check_env", Config: []string{`{type: command, path: {{.WorkDir}}/test/test-report-env.sh}`}, ExpectStepReports: []expectStep{ expectStep{ ExpectedEdge: hooks.Pre, ExpectStatus: hooks.StepOk, OutputTest: containsTest(fmt.Sprintf("TEST pre_testing %s@%s", testFSName, testSnapshotName)), }, expectStep{ExpectedEdge: hooks.Callback, ExpectStatus: hooks.StepOk}, expectStep{ ExpectedEdge: hooks.Post, ExpectStatus: hooks.StepOk, OutputTest: containsTest(fmt.Sprintf("TEST post_testing %s@%s", testFSName, testSnapshotName)), }, }, }, testCase{ Name: "pre_error_cancels_post", Config: []string{`{type: command, path: {{.WorkDir}}/test/test-pre-error-post-ok.sh}`}, ExpectHadError: true, ExpectHadFatalErr: false, ExpectStepReports: []expectStep{ expectStep{ ExpectedEdge: hooks.Pre, ExpectStatus: hooks.StepErr, OutputTest: containsTest(fmt.Sprintf("TEST ERROR pre_testing %s@%s", testFSName, testSnapshotName)), ErrorTest: regexpTest("^command hook invocation.*exit status 1$"), }, expectStep{ExpectedEdge: hooks.Callback, ExpectStatus: hooks.StepOk}, expectStep{ ExpectedEdge: hooks.Post, ExpectStatus: hooks.StepSkippedDueToPreErr, }, }, }, testCase{ Name: "pre_error_does_not_cancel_other_posts_but_itself", Config: []string{ `{type: command, path: {{.WorkDir}}/test/test-report-env.sh}`, `{type: command, path: {{.WorkDir}}/test/test-pre-error-post-ok.sh}`, }, ExpectHadError: true, ExpectHadFatalErr: false, ExpectStepReports: []expectStep{ expectStep{ ExpectedEdge: hooks.Pre, ExpectStatus: hooks.StepOk, OutputTest: containsTest(fmt.Sprintf("TEST pre_testing %s@%s", testFSName, testSnapshotName)), }, expectStep{ ExpectedEdge: hooks.Pre, ExpectStatus: hooks.StepErr, OutputTest: containsTest(fmt.Sprintf("TEST ERROR pre_testing %s@%s", testFSName, testSnapshotName)), ErrorTest: regexpTest("^command hook invocation.*exit status 1$"), }, expectStep{ExpectedEdge: hooks.Callback, ExpectStatus: hooks.StepOk}, expectStep{ ExpectedEdge: hooks.Post, ExpectStatus: hooks.StepSkippedDueToPreErr, }, expectStep{ ExpectedEdge: hooks.Post, ExpectStatus: hooks.StepOk, OutputTest: containsTest(fmt.Sprintf("TEST post_testing %s@%s", testFSName, testSnapshotName)), }, }, }, testCase{ Name: "exceed_buffer_limit", SuppressOutput: true, Config: []string{`{type: command, path: {{.WorkDir}}/test/test-large-stdout.sh}`}, ExpectHadError: false, ExpectHadFatalErr: false, ExpectStepReports: []expectStep{ expectStep{ ExpectedEdge: hooks.Pre, ExpectStatus: hooks.StepOk, OutputTest: func(t require.TestingT, s interface{}, v ...interface{}) { require.Len(t, s, 1<<20) }, }, expectStep{ExpectedEdge: hooks.Callback, ExpectStatus: hooks.StepOk}, expectStep{ // No-action run of above hook ExpectedEdge: hooks.Post, ExpectStatus: hooks.StepOk, OutputTest: require.Empty, }, }, }, /* Following not intended to test functionality of filter package. Only to demonstrate that hook filters are being applied. The following should result in NO hooks running. If it does run, a fatal hooks.RunReport will be returned. */ testCase{ Name: "exclude_all_filesystems", Config: []string{ `{type: command, path: {{.WorkDir}}/test/test-error.sh, err_is_fatal: true, filesystems: {"<": false}}`, }, ExpectStepReports: []expectStep{ expectStep{ ExpectedEdge: hooks.Callback, ExpectStatus: hooks.StepOk, }, }, }, } parseHookConfig := func(t *testing.T, in string) *config.Config { t.Helper() conf, err := config.ParseConfigBytes([]byte(in)) require.NoError(t, err) require.NotNil(t, conf) return conf } fillHooks := func(tt *testCase) string { // make hook path absolute cwd, err := os.Getwd() if err != nil { panic("os.Getwd() failed") } var hooksTmpl string = "\n" for _, l := range tt.Config { hooksTmpl += fmt.Sprintf(" - %s\n", l) } tmpl.New("List").Parse(hooksTmpl) var outBytes bytes.Buffer data := struct { WorkDir string }{ WorkDir: cwd, } if err := tmpl.Execute(&outBytes, data); err != nil { panic(err) } return outBytes.String() } var c *config.Config fs, err := zfs.NewDatasetPath(testFSName) require.NoError(t, err) log := logger.NewTestLogger(t) var cbReached bool cb := hooks.NewCallbackHookForFilesystem("testcallback", fs, func(_ context.Context) error { cbReached = true return nil }) hookEnvExtra := hooks.Env{ hooks.EnvFS: fs.ToString(), hooks.EnvSnapshot: testSnapshotName, } for _, tt := range testTable { if testing.Short() && tt.IsSlow { continue } t.Run(tt.Name, func(t *testing.T) { c = parseHookConfig(t, fillHooks(&tt)) snp := c.Jobs[0].Ret.(*config.SnapJob).Snapshotting.Ret.(*config.SnapshottingPeriodic) hookList, err := hooks.ListFromConfig(&snp.Hooks) require.NoError(t, err) filteredHooks, err := hookList.CopyFilteredForFilesystem(fs) require.NoError(t, err) plan, err := hooks.NewPlan(&filteredHooks, hooks.PhaseTesting, cb, hookEnvExtra) require.NoError(t, err) t.Logf("REPORT PRE EXECUTION:\n%s", plan.Report()) cbReached = false if testing.Verbose() && !tt.SuppressOutput { ctx = logging.WithLoggers(ctx, logging.SubsystemLoggersWithUniversalLogger(log)) } plan.Run(ctx, false) report := plan.Report() t.Logf("REPORT POST EXECUTION:\n%s", report) /* * TEST ASSERTIONS */ t.Logf("len(runReports)=%v", len(report)) t.Logf("len(tt.ExpectStepReports)=%v", len(tt.ExpectStepReports)) require.Equal(t, len(tt.ExpectStepReports), len(report), "ExpectStepReports must be same length as expected number of hook runs, excluding possible Callback") // Check if callback ran, when required if tt.ExpectCallbackSkipped { require.False(t, cbReached, "callback ran but should not have run") } else { require.True(t, cbReached, "callback should have run but did not") } // Check if a fatal run error occurred and was expected require.Equal(t, tt.ExpectHadFatalErr, report.HadFatalError(), "non-matching HadFatalError") require.Equal(t, tt.ExpectHadError, report.HadError(), "non-matching HadError") if tt.ExpectHadFatalErr { require.True(t, tt.ExpectHadError, "ExpectHadFatalErr implies ExpectHadError") } if !tt.ExpectHadError { require.False(t, tt.ExpectHadFatalErr, "!ExpectHadError implies !ExpectHadFatalErr") } // Iterate through each expected hook run for i, hook := range tt.ExpectStepReports { t.Logf("expecting report conforming to %v", hook) exp, act := hook.ExpectStatus, report[i].Status require.Equal(t, exp, act, "%s != %s", exp, act) // Check for required ExpectedEdge require.NotZero(t, hook.ExpectedEdge, "each hook must have an ExpectedEdge") require.Equal(t, hook.ExpectedEdge, report[i].Edge, "incorrect edge: expected %q, actual %q", hook.ExpectedEdge.String(), report[i].Edge.String(), ) // Check for expected output if hook.OutputTest != nil { require.IsType(t, (*hooks.CommandHookReport)(nil), report[i].Report) chr := report[i].Report.(*hooks.CommandHookReport) hook.OutputTest(t, string(chr.CapturedStdoutStderrCombined)) } // Check for expected errors if hook.ErrorTest != nil { hook.ErrorTest(t, string(report[i].Report.Error())) } } }) } }