diff --git a/internal/recovery/process.go b/internal/recovery/process.go index a7d6a8c..38eb4f1 100644 --- a/internal/recovery/process.go +++ b/internal/recovery/process.go @@ -5,13 +5,50 @@ package recovery import ( "context" + "errors" "fmt" "os" "os/exec" + "sync" "syscall" "time" ) +// maxCapturedOutput bounds what Process keeps from the child's stdout and +// stderr. Stalwart logs continuously once it is up, so this keeps the most +// recent output rather than the whole session - which is also what a +// failure needs, since the reason a server died is at the end of its log. +const maxCapturedOutput = 64 << 10 + +// outputBuffer collects the child process's combined output for use in +// error messages. exec.Cmd writes to it from its own goroutine while the +// supervising goroutine may read it, hence the mutex. +type outputBuffer struct { + mu sync.Mutex + buf []byte + truncated bool +} + +func (b *outputBuffer) Write(p []byte) (int, error) { + b.mu.Lock() + defer b.mu.Unlock() + b.buf = append(b.buf, p...) + if len(b.buf) > maxCapturedOutput { + b.buf = b.buf[len(b.buf)-maxCapturedOutput:] + b.truncated = true + } + return len(p), nil +} + +func (b *outputBuffer) String() string { + b.mu.Lock() + defer b.mu.Unlock() + if b.truncated { + return "...(earlier output truncated)...\n" + string(b.buf) + } + return string(b.buf) +} + // ProcessOptions configures how the target binary is launched. type ProcessOptions struct { BinaryPath string @@ -39,8 +76,27 @@ type ProcessOptions struct { // child process, so a caller can start it, wait for it to become healthy, // interact with it, and stop it again - without ever touching a real // systemd unit or Docker container. See ARCHITECTURE.md ยง4.4. +// +// It captures the child's output. That is not a nicety: a smoke test +// against a real 0.15.5 instance spent several rounds diagnosing a recovery +// boot that failed because port 8080 was already in use, and the tool +// reported only "connection refused" after a 60-second timeout - while +// Stalwart had printed "Failed to bind to [::]:8080: Address already in +// use" immediately, to a pipe nothing was reading. Anything that reports a +// supervised process failing must be able to say why. type Process struct { - cmd *exec.Cmd + cmd *exec.Cmd + output *outputBuffer +} + +// Output returns what the child has written to stdout and stderr so far, +// most-recent-first-truncated if it exceeded maxCapturedOutput. Safe to +// call at any point, including before Start and after Stop. +func (p *Process) Output() string { + if p.output == nil { + return "" + } + return p.output.String() } // Start launches the binary. It returns as soon as the OS has started the @@ -58,6 +114,9 @@ func (p *Process) Start(ctx context.Context, o ProcessOptions) error { cmd := exec.CommandContext(ctx, o.BinaryPath, "--config", o.ConfigPath) cmd.Env = append(os.Environ(), env...) + p.output = &outputBuffer{} + cmd.Stdout = p.output + cmd.Stderr = p.output if err := cmd.Start(); err != nil { return fmt.Errorf("recovery: start %s: %w", o.BinaryPath, err) } @@ -74,7 +133,12 @@ func (p *Process) Stop(gracePeriod time.Duration) error { if p.cmd == nil || p.cmd.Process == nil { return nil } - if err := p.cmd.Process.Signal(syscall.SIGTERM); err != nil { + // A process that already exited on its own still has to be reaped: + // cmd.Wait is what collects its status and, crucially, waits for the + // goroutines copying its output into our buffer. Returning early here + // would discard that output in exactly the case where it matters most - + // the server died by itself and its log says why. + if err := p.cmd.Process.Signal(syscall.SIGTERM); err != nil && !errors.Is(err, os.ErrProcessDone) { return fmt.Errorf("recovery: signal process (pid %d): %w", p.cmd.Process.Pid, err) } diff --git a/internal/recovery/process_test.go b/internal/recovery/process_test.go index 1201b4f..1fdfe6c 100644 --- a/internal/recovery/process_test.go +++ b/internal/recovery/process_test.go @@ -9,6 +9,7 @@ import ( "net" "os" "path/filepath" + "strings" "testing" "time" ) @@ -105,3 +106,73 @@ func TestWaitForHealthyTimesOut(t *testing.T) { t.Fatal("WaitForHealthy should time out when nothing is listening") } } + +// The bug this guards against cost several rounds of diagnosis against a +// real Stalwart: recovery mode failed because port 8080 was already in use, +// Stalwart said exactly that immediately, and the tool discarded it and +// reported only a 60-second timeout and "connection refused". The helper +// process here fails the same way - it can't bind its port and says so on +// stderr before exiting. +func TestProcessCapturesOutputFromAFailedStart(t *testing.T) { + // Occupy the port first, so the child's bind fails exactly as + // Stalwart's did. + ln, err := net.Listen("tcp", "127.0.0.1:0") + if err != nil { + t.Fatal(err) + } + defer ln.Close() + port := fmt.Sprint(ln.Addr().(*net.TCPAddr).Port) + + proc := &Process{} + if err := proc.Start(context.Background(), ProcessOptions{ + BinaryPath: os.Args[0], + ExtraEnv: []string{ + "STALWART_MIGRATOR_TEST_HELPER=1", + "STALWART_MIGRATOR_TEST_PORT=" + port, + }, + }); err != nil { + t.Fatalf("Start: %v", err) + } + + // Poll a port nothing is listening on, exactly as the real flow does: + // the tool waits for a listener that never appears while the child is + // busy failing and saying why. + err = WaitForHealthy(context.Background(), nil, "http://127.0.0.1:1/", time.Second) + if err == nil { + t.Fatal("WaitForHealthy should not have succeeded against an unreachable URL") + } + _ = proc.Stop(5 * time.Second) + + got := proc.Output() + if !strings.Contains(got, "fake stalwart: listen:") { + t.Errorf("captured output = %q, want the child's own bind failure - without it a caller can only report a timeout", got) + } +} + +func TestProcessOutputIsSafeBeforeStartAndAfterStop(t *testing.T) { + proc := &Process{} + if got := proc.Output(); got != "" { + t.Errorf("Output() before Start = %q, want empty", got) + } + if err := proc.Stop(time.Second); err != nil { + t.Errorf("Stop on an unstarted process: %v", err) + } +} + +// A long-lived server would otherwise grow this buffer without bound. +func TestOutputBufferKeepsTheMostRecentOutput(t *testing.T) { + b := &outputBuffer{} + for i := 0; i < 4000; i++ { + fmt.Fprintf(b, "line %d filler filler filler filler filler\n", i) + } + got := b.String() + if len(got) > maxCapturedOutput+64 { + t.Errorf("buffer grew to %d bytes, want it bounded near %d", len(got), maxCapturedOutput) + } + if !strings.Contains(got, "line 3999") { + t.Error("the most recent output was dropped; a failure's reason is at the end of the log") + } + if !strings.Contains(got, "truncated") { + t.Error("truncation should be visible, not silent") + } +} diff --git a/internal/recovery/recovery.go b/internal/recovery/recovery.go index a702391..63720d8 100644 --- a/internal/recovery/recovery.go +++ b/internal/recovery/recovery.go @@ -9,6 +9,7 @@ import ( "encoding/hex" "fmt" "net/http" + "strings" "time" "github.com/LINUXexpert-org/stalwart-migrator/internal/checkpoint" @@ -87,13 +88,13 @@ func Run(ctx context.Context, store *checkpoint.Store, rs *checkpoint.RunState, startupTimeout = 60 * time.Second } if healthErr := WaitForHealthy(ctx, opts.HTTPClient, opts.ListenURL, startupTimeout); healthErr != nil { - return checkpoint.StepOutcome{}, fmt.Errorf("recovery mode did not come up: %w", healthErr) + return checkpoint.StepOutcome{}, fmt.Errorf("recovery mode did not come up: %w%s", healthErr, outputSuffix(proc)) } if applyErr := ApplyAll(ctx, ApplyOptions{ CLIBinaryPath: opts.CLIBinaryPath, URL: opts.ListenURL, User: opts.AdminUser, Password: password, }, opts.ApplyFiles); applyErr != nil { - return checkpoint.StepOutcome{}, fmt.Errorf("settings apply failed: %w", applyErr) + return checkpoint.StepOutcome{}, fmt.Errorf("settings apply failed: %w%s", applyErr, outputSuffix(proc)) } return checkpoint.StepOutcome{ @@ -108,3 +109,16 @@ func Run(ctx context.Context, store *checkpoint.Store, rs *checkpoint.RunState, report.Results = append(report.Results, CheckResult{Name: "recovery-cycle", Status: StatusOK, Detail: outcome.Detail}) return report, nil } + +// outputSuffix renders a supervised process's captured output for +// appending to an error, or nothing if it produced none. The server's own +// words are usually the whole diagnosis - a bind conflict, a rejected +// config value - and without them the caller is left guessing at a +// timeout. +func outputSuffix(proc *Process) string { + out := strings.TrimSpace(proc.Output()) + if out == "" { + return " (the process produced no output)" + } + return fmt.Sprintf("\n--- output from the supervised Stalwart process ---\n%s\n--- end of output ---", out) +} diff --git a/internal/validate/bootcheck.go b/internal/validate/bootcheck.go index 6cb3d93..2d54e39 100644 --- a/internal/validate/bootcheck.go +++ b/internal/validate/bootcheck.go @@ -7,6 +7,7 @@ import ( "context" "fmt" "net/http" + "strings" "time" "github.com/LINUXexpert-org/stalwart-migrator/internal/checkpoint" @@ -80,7 +81,12 @@ func BootCheck(ctx context.Context, o BootCheckOptions) (detail string, result * timeout = 30 * time.Second } if healthErr := recovery.WaitForHealthy(ctx, o.HTTPClient, o.ListenURL, timeout); healthErr != nil { - return "", nil, fmt.Errorf("migrated instance did not come up under a normal (non-recovery-mode) boot: %w", healthErr) + out := strings.TrimSpace(proc.Output()) + if out == "" { + out = "(the process produced no output)" + } + return "", nil, fmt.Errorf("migrated instance did not come up under a normal (non-recovery-mode) boot: %w\n"+ + "--- output from the supervised Stalwart process ---\n%s\n--- end of output ---", healthErr, out) } detail = fmt.Sprintf("migrated instance booted normally (not in recovery mode) and answered at %s", o.ListenURL)