diff --git a/CHANGELOG.md b/CHANGELOG.md index 7d1dceaca..ab4301079 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -36,6 +36,12 @@ Versioning](http://semver.org/spec/v2.0.0.html) except to the first release. * New `MockRequestNamed` type for verifying specific requests in tests. * New `test_helpers.ExecuteOnAll` function to execute operations on all instances in parallel with context support. +* New `(*test_helpers.TarantoolInstance).LogTail()` method that returns + the last 50 lines of captured tarantool stdout/stderr (#147). +* New `test_helpers.DumpLogsIfFailed(t, inst)` helper that prints the + captured tarantool log via `t.Logf` when the test failed — intended + for `defer test_helpers.DumpLogsIfFailed(t, inst)` after a successful + `StartTarantool` (#147). ### Changed @@ -109,6 +115,18 @@ Versioning](http://semver.org/spec/v2.0.0.html) except to the first release. * Fixed the fluctuating behavior of the TestConnectionHandlerOpenUpdateClose test by increasing the waiting time (#502). +* On Linux, tarantool processes started by `test_helpers.StartTarantool` + are now terminated when the parent test process dies, preventing leaked + instances after a panic (#147). +* `test_helpers.StartTarantool` now captures the last lines of the + spawned tarantool's stdout/stderr and includes them in the returned + error when startup fails, so test failures show the underlying + tarantool error directly instead of just "exit status 1" or a + connection timeout (#147). +* Reordered tests to defer `test_helpers.StopTarantoolWithCleanup` only + after asserting `StartTarantool` did not return an error, so a failed + start no longer panics with a nil-pointer dereference in the deferred + cleanup (#147). ## [v2.4.1] - 2025-10-16 diff --git a/arrow/tarantool_test.go b/arrow/tarantool_test.go index f99ef73dc..79265d52b 100644 --- a/arrow/tarantool_test.go +++ b/arrow/tarantool_test.go @@ -108,12 +108,11 @@ func runTestMain(m *testing.M) int { ConnectRetry: 10, RetryTimeout: 500 * time.Millisecond, }) - defer test_helpers.StopTarantoolWithCleanup(instance) - if err != nil { log.Printf("Failed to prepare test Tarantool: %s", err) return 1 } + defer test_helpers.StopTarantoolWithCleanup(instance) return m.Run() } diff --git a/crud/tarantool_test.go b/crud/tarantool_test.go index 08dde0587..03f177756 100644 --- a/crud/tarantool_test.go +++ b/crud/tarantool_test.go @@ -1446,12 +1446,11 @@ func TestYieldEveryOption(t *testing.T) { // https://stackoverflow.com/questions/27629380/how-to-exit-a-go-program-honoring-deferred-calls func runTestMain(m *testing.M) int { inst, err := test_helpers.StartTarantool(startOpts) - defer test_helpers.StopTarantoolWithCleanup(inst) - if err != nil { log.Printf("Failed to prepare test tarantool: %s", err) return 1 } + defer test_helpers.StopTarantoolWithCleanup(inst) return m.Run() } diff --git a/datetime/datetime_test.go b/datetime/datetime_test.go index 465d386c8..7d4aa78ed 100644 --- a/datetime/datetime_test.go +++ b/datetime/datetime_test.go @@ -981,12 +981,11 @@ func runTestMain(m *testing.M) int { ConnectRetry: 10, RetryTimeout: 500 * time.Millisecond, }) - defer test_helpers.StopTarantoolWithCleanup(instance) - if err != nil { log.Printf("Failed to prepare test Tarantool: %s", err) return 1 } + defer test_helpers.StopTarantoolWithCleanup(instance) return m.Run() } diff --git a/decimal/decimal_test.go b/decimal/decimal_test.go index a7f4cdc1c..50ba8c31e 100644 --- a/decimal/decimal_test.go +++ b/decimal/decimal_test.go @@ -599,12 +599,11 @@ func runTestMain(m *testing.M) int { ConnectRetry: 10, RetryTimeout: 500 * time.Millisecond, }) - defer test_helpers.StopTarantoolWithCleanup(instance) - if err != nil { log.Printf("Failed to prepare test Tarantool: %s", err) return 1 } + defer test_helpers.StopTarantoolWithCleanup(instance) return m.Run() } diff --git a/tarantool_test.go b/tarantool_test.go index 56dabf6ea..b654acfe1 100644 --- a/tarantool_test.go +++ b/tarantool_test.go @@ -2762,8 +2762,8 @@ func newWatcherReconnectionPrepareTestConnection(t *testing.T) (*Connection, con ConnectRetry: 10, RetryTimeout: 500 * time.Millisecond, }) - t.Cleanup(func() { test_helpers.StopTarantoolWithCleanup(inst) }) require.NoErrorf(t, err, "Unable to start Tarantool") + t.Cleanup(func() { test_helpers.StopTarantoolWithCleanup(inst) }) ctx, cancel := test_helpers.GetConnectContext() @@ -2843,8 +2843,8 @@ func TestConnection_NewWatcher_reconnect(t *testing.T) { ConnectRetry: 10, RetryTimeout: 500 * time.Millisecond, }) - defer test_helpers.StopTarantoolWithCleanup(inst) require.NoErrorf(t, err, "Unable to start Tarantool") + defer test_helpers.StopTarantoolWithCleanup(inst) reconnectOpts := opts reconnectOpts.Reconnect = 100 * time.Millisecond @@ -3097,8 +3097,8 @@ func TestConnection_named_index_after_reconnect(t *testing.T) { ConnectRetry: 10, RetryTimeout: 500 * time.Millisecond, }) - defer test_helpers.StopTarantoolWithCleanup(inst) require.NoErrorf(t, err, "Unable to start Tarantool") + defer test_helpers.StopTarantoolWithCleanup(inst) reconnectOpts := opts reconnectOpts.Reconnect = 100 * time.Millisecond @@ -3205,8 +3205,8 @@ func TestConnectIsBlocked(t *testing.T) { ConnectRetry: 10, RetryTimeout: 500 * time.Millisecond, }) - defer test_helpers.StopTarantoolWithCleanup(inst) require.NoErrorf(t, err, "Unable to start Tarantool") + defer test_helpers.StopTarantoolWithCleanup(inst) var counter int mockDialer := mockSlowDialer{original: testDialer, counter: &counter} diff --git a/test_helpers/cmd_linux.go b/test_helpers/cmd_linux.go new file mode 100644 index 000000000..9f46a7ce4 --- /dev/null +++ b/test_helpers/cmd_linux.go @@ -0,0 +1,21 @@ +//go:build linux + +package test_helpers + +import ( + "os/exec" + "syscall" +) + +// commandKillOnExit returns an *exec.Cmd that will be terminated by the +// kernel when the parent process dies, see +// https://github.com/golang/go/issues/37206. Without this, a panic in a +// test leaves the spawned tarantool process running and blocking the TCP +// port for subsequent runs (issue #147). +func commandKillOnExit(name string, arg ...string) *exec.Cmd { + cmd := exec.Command(name, arg...) + cmd.SysProcAttr = &syscall.SysProcAttr{ + Pdeathsig: syscall.SIGTERM, + } + return cmd +} diff --git a/test_helpers/cmd_other.go b/test_helpers/cmd_other.go new file mode 100644 index 000000000..933642fa6 --- /dev/null +++ b/test_helpers/cmd_other.go @@ -0,0 +1,14 @@ +//go:build !linux + +package test_helpers + +import ( + "os/exec" +) + +// commandKillOnExit is a fallback for platforms without a Pdeathsig +// equivalent. It just delegates to exec.Command, so a parent panic may +// leave the tarantool child alive (issue #147). +func commandKillOnExit(name string, arg ...string) *exec.Cmd { + return exec.Command(name, arg...) +} diff --git a/test_helpers/log_buffer.go b/test_helpers/log_buffer.go new file mode 100644 index 000000000..ebf47ae5d --- /dev/null +++ b/test_helpers/log_buffer.go @@ -0,0 +1,87 @@ +package test_helpers + +import ( + "bytes" + "strings" + "sync" +) + +// logTailLines is the number of trailing log lines kept for a started +// tarantool instance. Shown in the StartTarantool error to help diagnose +// failures from CI logs without re-running the test. +const logTailLines = 50 + +// logTailBuffer is an io.Writer that keeps the last logTailLines lines +// written to it. Safe for concurrent writes from exec.Cmd's stdout and +// stderr copy goroutines. +type logTailBuffer struct { + mu sync.Mutex + lines []string + pending []byte + max int +} + +func newLogTailBuffer(maxLines int) *logTailBuffer { + return &logTailBuffer{max: maxLines} +} + +func (b *logTailBuffer) Write(p []byte) (int, error) { + b.mu.Lock() + defer b.mu.Unlock() + + b.pending = append(b.pending, p...) + for { + i := bytes.IndexByte(b.pending, '\n') + if i < 0 { + break + } + b.appendLine(string(b.pending[:i])) + b.pending = b.pending[i+1:] + } + return len(p), nil +} + +func (b *logTailBuffer) appendLine(line string) { + if len(b.lines) >= b.max { + copy(b.lines, b.lines[1:]) + b.lines = b.lines[:len(b.lines)-1] + } + b.lines = append(b.lines, line) +} + +// formatLogTail returns a "\n--- last N lines of tarantool log ---\n..." +// suffix suitable for appending to a StartTarantool error. Returns an +// empty string when the buffer captured nothing. +func formatLogTail(b *logTailBuffer) string { + if b == nil { + return "" + } + tail := b.Tail() + if tail == "" { + return "" + } + return "\n--- last tarantool log lines ---\n" + tail + "--- end of tarantool log ---" +} + +// Tail returns the buffered output as a single string with a trailing +// newline if non-empty, including any partial line that was not yet +// terminated by '\n'. +func (b *logTailBuffer) Tail() string { + b.mu.Lock() + defer b.mu.Unlock() + + if len(b.lines) == 0 && len(b.pending) == 0 { + return "" + } + + var sb strings.Builder + for _, l := range b.lines { + sb.WriteString(l) + sb.WriteByte('\n') + } + if len(b.pending) > 0 { + sb.Write(b.pending) + sb.WriteByte('\n') + } + return sb.String() +} diff --git a/test_helpers/log_buffer_test.go b/test_helpers/log_buffer_test.go new file mode 100644 index 000000000..b4bfb09c2 --- /dev/null +++ b/test_helpers/log_buffer_test.go @@ -0,0 +1,72 @@ +package test_helpers + +import ( + "fmt" + "strings" + "testing" +) + +func TestLogTailBuffer_KeepsLastNLines(t *testing.T) { + b := newLogTailBuffer(3) + for i := 1; i <= 5; i++ { + _, _ = fmt.Fprintf(b, "line %d\n", i) + } + got := b.Tail() + want := "line 3\nline 4\nline 5\n" + if got != want { + t.Fatalf("Tail mismatch:\n got: %q\nwant: %q", got, want) + } +} + +func TestLogTailBuffer_PartialLine(t *testing.T) { + b := newLogTailBuffer(5) + if _, err := b.Write([]byte("hello ")); err != nil { + t.Fatalf("Write: %v", err) + } + if _, err := b.Write([]byte("world")); err != nil { + t.Fatalf("Write: %v", err) + } + got := b.Tail() + if got != "hello world\n" { + t.Fatalf("Tail mismatch: got %q", got) + } +} + +func TestLogTailBuffer_SplitWrites(t *testing.T) { + b := newLogTailBuffer(5) + _, _ = b.Write([]byte("first\nsecon")) + _, _ = b.Write([]byte("d\nthird\n")) + got := b.Tail() + want := "first\nsecond\nthird\n" + if got != want { + t.Fatalf("Tail mismatch:\n got: %q\nwant: %q", got, want) + } +} + +func TestLogTailBuffer_Empty(t *testing.T) { + b := newLogTailBuffer(5) + if got := b.Tail(); got != "" { + t.Fatalf("expected empty, got %q", got) + } + if got := formatLogTail(b); got != "" { + t.Fatalf("expected empty formatLogTail, got %q", got) + } + if got := formatLogTail(nil); got != "" { + t.Fatalf("expected empty formatLogTail(nil), got %q", got) + } +} + +func TestFormatLogTail_Wraps(t *testing.T) { + b := newLogTailBuffer(5) + _, _ = b.Write([]byte("boom\n")) + got := formatLogTail(b) + if !strings.Contains(got, "--- last tarantool log lines ---") { + t.Fatalf("missing header: %q", got) + } + if !strings.Contains(got, "boom") { + t.Fatalf("missing line: %q", got) + } + if !strings.HasSuffix(got, "--- end of tarantool log ---") { + t.Fatalf("missing footer: %q", got) + } +} diff --git a/test_helpers/log_dump.go b/test_helpers/log_dump.go new file mode 100644 index 000000000..ebba8ab68 --- /dev/null +++ b/test_helpers/log_dump.go @@ -0,0 +1,29 @@ +package test_helpers + +// failedLogger is the subset of *testing.T needed by DumpLogsIfFailed. +// Kept separate from T so adding Failed/Logf does not change the public +// T interface contract. +type failedLogger interface { + Helper() + Failed() bool + Logf(format string, args ...any) +} + +// DumpLogsIfFailed prints the tail of the tarantool instance's captured +// stdout/stderr via t.Logf when the test has already failed. Intended +// for use as `defer test_helpers.DumpLogsIfFailed(t, inst)` right after +// a successful StartTarantool, so an assertion failure later in the +// test surfaces the corresponding tarantool log alongside the failure. +// +// No-op when the test passed, the instance is nil, or no log was captured. +func DumpLogsIfFailed(t failedLogger, inst *TarantoolInstance) { + t.Helper() + if !t.Failed() || inst == nil { + return + } + tail := inst.LogTail() + if tail == "" { + return + } + t.Logf("tarantool %q log tail:\n%s", inst.Opts.Listen, tail) +} diff --git a/test_helpers/log_dump_test.go b/test_helpers/log_dump_test.go new file mode 100644 index 000000000..61465a891 --- /dev/null +++ b/test_helpers/log_dump_test.go @@ -0,0 +1,77 @@ +package test_helpers + +import ( + "fmt" + "strings" + "testing" +) + +type fakeT struct { + failed bool + logs []string + helped int +} + +func (f *fakeT) Helper() { f.helped++ } +func (f *fakeT) Failed() bool { return f.failed } +func (f *fakeT) Logf(format string, args ...any) { + f.logs = append(f.logs, fmt.Sprintf(format, args...)) +} + +func newInstWithLog(lines ...string) *TarantoolInstance { + inst := &TarantoolInstance{log: newLogTailBuffer(logTailLines)} + inst.Opts.Listen = "127.0.0.1:1234" + for _, l := range lines { + _, _ = fmt.Fprintln(inst.log, l) + } + return inst +} + +func TestDumpLogsIfFailed_PassedTest(t *testing.T) { + ft := &fakeT{failed: false} + DumpLogsIfFailed(ft, newInstWithLog("oops")) + if len(ft.logs) != 0 { + t.Fatalf("expected no logs on passing test, got %v", ft.logs) + } +} + +func TestDumpLogsIfFailed_FailedTest(t *testing.T) { + ft := &fakeT{failed: true} + DumpLogsIfFailed(ft, newInstWithLog("oops", "more context")) + if len(ft.logs) != 1 { + t.Fatalf("expected one log, got %v", ft.logs) + } + if !strings.Contains(ft.logs[0], "oops") || !strings.Contains(ft.logs[0], "more context") { + t.Fatalf("missing log content: %q", ft.logs[0]) + } + if !strings.Contains(ft.logs[0], "127.0.0.1:1234") { + t.Fatalf("missing listen address: %q", ft.logs[0]) + } +} + +func TestDumpLogsIfFailed_NilInstance(t *testing.T) { + ft := &fakeT{failed: true} + DumpLogsIfFailed(ft, nil) + if len(ft.logs) != 0 { + t.Fatalf("expected no logs for nil instance, got %v", ft.logs) + } +} + +func TestDumpLogsIfFailed_EmptyLog(t *testing.T) { + ft := &fakeT{failed: true} + DumpLogsIfFailed(ft, newInstWithLog()) + if len(ft.logs) != 0 { + t.Fatalf("expected no logs for empty buffer, got %v", ft.logs) + } +} + +func TestTarantoolInstance_LogTail_Nil(t *testing.T) { + var inst *TarantoolInstance + if got := inst.LogTail(); got != "" { + t.Fatalf("nil receiver: got %q", got) + } + inst2 := &TarantoolInstance{} + if got := inst2.LogTail(); got != "" { + t.Fatalf("no buffer: got %q", got) + } +} diff --git a/test_helpers/main.go b/test_helpers/main.go index 77f88fb3a..96488a88f 100644 --- a/test_helpers/main.go +++ b/test_helpers/main.go @@ -99,7 +99,8 @@ type TarantoolInstance struct { // Dialer to check that connection established. Dialer tarantool.Dialer - st chan state + st chan state + log *logTailBuffer } // T is a subset of testing.T interface used by test helpers. @@ -201,6 +202,17 @@ func (t *TarantoolInstance) Signal(sig os.Signal) error { return t.Cmd.Process.Signal(sig) } +// LogTail returns the tail of the spawned tarantool's combined +// stdout/stderr captured since the process was started — up to +// the last 50 lines. Includes a partial trailing line if the +// process did not flush a newline. Empty if no output was captured. +func (t *TarantoolInstance) LogTail() string { + if t == nil || t.log == nil { + return "" + } + return t.log.Tail() +} + func isReady(dialer tarantool.Dialer, opts *tarantool.Opts) error { var err error var conn *tarantool.Connection @@ -345,6 +357,7 @@ func RestartTarantool(inst *TarantoolInstance) error { inst.Cmd.Process = startedInst.Cmd.Process inst.st = startedInst.st + inst.log = startedInst.log return err } @@ -401,7 +414,8 @@ func prepareDir(workDir string) (string, error) { func StartTarantool(startOpts StartOpts) (*TarantoolInstance, error) { // Prepare tarantool command. inst := &TarantoolInstance{ - st: make(chan state, 1), + st: make(chan state, 1), + log: newLogTailBuffer(logTailLines), } init := state{ done: make(chan struct{}), @@ -430,8 +444,10 @@ func StartTarantool(startOpts StartOpts) (*TarantoolInstance, error) { args = append(args, "--config", startOpts.ConfigFile) args = append(args, "--name", startOpts.InstanceName) } - inst.Cmd = exec.Command(getTarantoolExec(), args...) + inst.Cmd = commandKillOnExit(getTarantoolExec(), args...) inst.Cmd.Dir = startOpts.WorkDir + inst.Cmd.Stdout = inst.log + inst.Cmd.Stderr = inst.log inst.Cmd.Env = append( os.Environ(), @@ -485,15 +501,16 @@ func StartTarantool(startOpts StartOpts) (*TarantoolInstance, error) { } if inst.IsExit() && inst.result() != nil { + runErr := inst.result() StopTarantool(inst) - return nil, fmt.Errorf("unexpected terminated Tarantool %q: %w", - inst.Opts.Listen, inst.result()) + return nil, fmt.Errorf("unexpected terminated Tarantool %q: %w%s", + inst.Opts.Listen, runErr, formatLogTail(inst.log)) } if err != nil { StopTarantool(inst) - return nil, fmt.Errorf("failed to connect Tarantool %q: %w", - inst.Opts.Listen, err) + return nil, fmt.Errorf("failed to connect Tarantool %q: %w%s", + inst.Opts.Listen, err, formatLogTail(inst.log)) } return inst, nil diff --git a/uuid/uuid_test.go b/uuid/uuid_test.go index b5ad93b0e..2c47120e7 100644 --- a/uuid/uuid_test.go +++ b/uuid/uuid_test.go @@ -149,12 +149,11 @@ func runTestMain(m *testing.M) int { ConnectRetry: 10, RetryTimeout: 500 * time.Millisecond, }) - defer test_helpers.StopTarantoolWithCleanup(inst) - if err != nil { log.Printf("Failed to prepare test tarantool: %s", err) return 1 } + defer test_helpers.StopTarantoolWithCleanup(inst) return m.Run() }