From 290fd2dc4e0766ef110ea3d1b8641c5b73b6106a Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Carlos=20Flor=C3=AAncio?= Date: Fri, 14 Aug 2026 13:58:32 +0100 Subject: [PATCH] fix: avoid plugin shutdown log noise (#2661) --- apps/backend/cmd/kandev/main.go | 16 ++ apps/backend/cmd/kandev/main_test.go | 26 ++ apps/backend/internal/launcher/dev.go | 1 + apps/backend/internal/launcher/dev_test.go | 1 + apps/backend/internal/launcher/env.go | 11 + apps/backend/internal/launcher/process.go | 144 +++++++--- .../launcher/process_group_default.go | 16 ++ .../internal/launcher/process_group_unix.go | 23 ++ .../launcher/process_group_unix_test.go | 260 +++++++++++++++++- .../launcher/process_group_windows.go | 18 ++ .../plan.md | 137 +++++++++ .../task-01-launcher-graceful-signal.md | 98 +++++++ docs/specs/shutdown-log-noise/spec.md | 51 +++- 13 files changed, 758 insertions(+), 44 deletions(-) create mode 100644 docs/plans/shutdown-plugin-process-group-teardown/plan.md create mode 100644 docs/plans/shutdown-plugin-process-group-teardown/task-01-launcher-graceful-signal.md diff --git a/apps/backend/cmd/kandev/main.go b/apps/backend/cmd/kandev/main.go index 249ef7f73a..978e251980 100644 --- a/apps/backend/cmd/kandev/main.go +++ b/apps/backend/cmd/kandev/main.go @@ -1,7 +1,9 @@ package main import ( + "fmt" "os" + "strconv" "github.com/kandev/kandev/internal/backendapp" "github.com/kandev/kandev/internal/launcher" @@ -15,6 +17,8 @@ var ( BuildTime = "unknown" ) +const backendPIDFileEnv = "KANDEV_BACKEND_PID_FILE" + type buildInfo struct { Version string Commit string @@ -35,6 +39,10 @@ func run(args []string) int { func dispatch(args []string, build buildInfo, backend backendRunner, launch launcherRunner) int { if len(args) > 0 && args[0] == "__backend" { + if err := writeBackendPIDFile(); err != nil { + fmt.Fprintf(os.Stderr, "failed to write backend pid file: %v\n", err) + return 1 + } return backend(args[1:], backendapp.BuildInfo{ Version: build.Version, Commit: build.Commit, @@ -47,3 +55,11 @@ func dispatch(args []string, build buildInfo, backend backendRunner, launch laun BuildTime: build.BuildTime, }) } + +func writeBackendPIDFile() error { + path := os.Getenv(backendPIDFileEnv) + if path == "" { + return nil + } + return os.WriteFile(path, []byte(strconv.Itoa(os.Getpid())+"\n"), 0o600) +} diff --git a/apps/backend/cmd/kandev/main_test.go b/apps/backend/cmd/kandev/main_test.go index 4e7db98222..1ffc4c09df 100644 --- a/apps/backend/cmd/kandev/main_test.go +++ b/apps/backend/cmd/kandev/main_test.go @@ -1,6 +1,10 @@ package main import ( + "os" + "path/filepath" + "strconv" + "strings" "testing" "github.com/kandev/kandev/internal/backendapp" @@ -36,6 +40,28 @@ func TestDispatchesHiddenBackendMode(t *testing.T) { } } +func TestDispatchWritesBackendPIDFile(t *testing.T) { + pidFile := filepath.Join(t.TempDir(), "backend.pid") + t.Setenv(backendPIDFileEnv, pidFile) + + code := dispatch([]string{"__backend"}, buildInfo{}, func([]string, backendapp.BuildInfo) int { + return 7 + }, func([]string, launcher.BuildInfo) int { + t.Fatal("launcher runner called for backend mode") + return 0 + }) + if code != 7 { + t.Fatalf("exit code = %d, want 7", code) + } + raw, err := os.ReadFile(pidFile) + if err != nil { + t.Fatalf("read backend pid file: %v", err) + } + if got, want := strings.TrimSpace(string(raw)), strconv.Itoa(os.Getpid()); got != want { + t.Fatalf("backend pid = %q, want %q", got, want) + } +} + func TestDispatchDefaultsToLauncherMode(t *testing.T) { backendCalled := false launcherCalled := false diff --git a/apps/backend/internal/launcher/dev.go b/apps/backend/internal/launcher/dev.go index 5463cc7a2a..e5c4e07ac8 100644 --- a/apps/backend/internal/launcher/dev.go +++ b/apps/backend/internal/launcher/dev.go @@ -41,6 +41,7 @@ func runDev(ctx context.Context, opts Options) int { return 1 } env := backendEnv(cfg.ports, cfg.logLevel, resolveConsoleLogLevel(opts), opts.Debug, healthToken, cfg.extra) + env = upsertEnv(env, backendPIDFileEnv, filepath.Join(devKandevHome(cfg.repoRoot), "supervisor", "backend.pid")) backend, dumpLogs, err := launchBackendFn(backendLaunchConfig{ Command: "make", Args: []string{"-C", "apps/backend", "dev"}, diff --git a/apps/backend/internal/launcher/dev_test.go b/apps/backend/internal/launcher/dev_test.go index 1701754881..aa27731570 100644 --- a/apps/backend/internal/launcher/dev_test.go +++ b/apps/backend/internal/launcher/dev_test.go @@ -115,6 +115,7 @@ func TestRunDevLaunchesBackendThenWebAndOpensBrowser(t *testing.T) { "KANDEV_DEBUG_DEV_MODE=true", "KANDEV_HOME_DIR=" + filepath.Join(repo, ".kandev-dev"), "KANDEV_DATABASE_PATH=", + "KANDEV_BACKEND_PID_FILE=" + filepath.Join(repo, ".kandev-dev", "supervisor", "backend.pid"), } { if !strings.Contains(backendEnv, expected) { t.Fatalf("backend environment missing %q:\n%s", expected, backendEnv) diff --git a/apps/backend/internal/launcher/env.go b/apps/backend/internal/launcher/env.go index 69240ac5f7..cde482d53b 100644 --- a/apps/backend/internal/launcher/env.go +++ b/apps/backend/internal/launcher/env.go @@ -10,6 +10,7 @@ import ( const healthTokenBytes = 32 const desktopNativeNotificationsEnabled = "true" +const backendPIDFileEnv = "KANDEV_BACKEND_PID_FILE" func newHealthToken() (string, error) { token := make([]byte, healthTokenBytes) @@ -66,6 +67,16 @@ func upsertEnv(env []string, key, value string) []string { return append(env, prefix+value) } +func processEnvValue(env []string, key string) string { + prefix := key + "=" + for _, item := range env { + if strings.HasPrefix(item, prefix) { + return strings.TrimPrefix(item, prefix) + } + } + return "" +} + func setEnvIfUnset(env []string, key, value string) []string { prefix := key + "=" for _, item := range env { diff --git a/apps/backend/internal/launcher/process.go b/apps/backend/internal/launcher/process.go index 5d12142817..b5bc2eecfb 100644 --- a/apps/backend/internal/launcher/process.go +++ b/apps/backend/internal/launcher/process.go @@ -7,6 +7,8 @@ import ( "os" "os/exec" "os/signal" + "strconv" + "strings" "sync" "sync/atomic" "syscall" @@ -24,6 +26,14 @@ var launcherShutdownDebug atomic.Bool var launcherStatusOutput io.Writer = os.Stderr var launcherExit = os.Exit +type gracefulSignalScope string + +const ( + gracefulSignalRootOnly gracefulSignalScope = "root-only" + gracefulSignalTreeWide gracefulSignalScope = "tree-wide" + gracefulSignalUnsupported gracefulSignalScope = "unsupported" +) + type processSupervisor struct { mu sync.Mutex children []*managedProcess @@ -31,12 +41,13 @@ type processSupervisor struct { } type managedProcess struct { - label string - cmd *exec.Cmd - exitCode int - exited bool - mu sync.Mutex - done chan struct{} + label string + cmd *exec.Cmd + gracefulPIDFile string + exitCode int + exited bool + mu sync.Mutex + done chan struct{} } type managedProcessShutdownResult struct { @@ -160,6 +171,12 @@ func startProcess(command string, args []string, cwd string, env []string, quiet cmd.Dir = cwd cmd.Env = env cmd.Stdin = nil + gracefulPIDFile := processEnvValue(env, backendPIDFileEnv) + if gracefulPIDFile != "" { + if err := os.Remove(gracefulPIDFile); err != nil && !errors.Is(err, os.ErrNotExist) { + return nil, nil, fmt.Errorf("remove backend pid file: %w", err) + } + } configureManagedProcess(cmd) stdout := newLimitedBuffer(capturedOutputLimit) var stdoutSink io.Writer @@ -173,7 +190,12 @@ func startProcess(command string, args []string, cwd string, env []string, quiet supervisor.mu.Unlock() return nil, nil, err } - proc := &managedProcess{label: label, cmd: cmd, done: make(chan struct{})} + proc := &managedProcess{ + label: label, + cmd: cmd, + gracefulPIDFile: gracefulPIDFile, + done: make(chan struct{}), + } supervisor.children = append(supervisor.children, proc) childCount := len(supervisor.children) supervisor.mu.Unlock() @@ -298,42 +320,24 @@ func (p *managedProcess) kill() managedProcessShutdownResult { result.pid = pid select { case <-p.done: - result.duration = time.Since(start) - result.graceful = true shutdownDebugf("managed process kill skipped; already exited label=%q pid=%d", p.label, pid) - return result + return p.finishGracefulShutdown(start, pid, result) default: } + targetPID, targetReady := p.gracefulTargetPID(pid) + scope := managedProcessGracefulScope(targetReady) shutdownDebugf("managed process kill begin label=%q pid=%d grace=%s", p.label, pid, managedProcessShutdownGrace) - shutdownDebugf("managed process group SIGTERM requested label=%q pgid=%d", p.label, pid) - if err := terminateManagedProcessGroup(pid); err != nil { - if errors.Is(err, syscall.ESRCH) { - result.duration = time.Since(start) - result.graceful = true - shutdownDebugf("managed process group already gone label=%q pid=%d", p.label, pid) - return result - } - shutdownDebugf("managed process group SIGTERM failed pid=%d err=%v; killing process", pid, err) - shutdownDebugf("managed process SIGKILL requested label=%q pid=%d reason=%q", p.label, pid, "sigterm_failed") - _ = p.cmd.Process.Kill() - result.forceKilled = true - result.err = err - if waitForManagedProcessKillDone(p.done, managedProcessForceKillWait) { - shutdownDebugf("managed process killed after SIGTERM failure pid=%d", pid) - } else { - result.err = errors.Join(result.err, fmt.Errorf("timed out waiting for process %d after SIGKILL", pid)) - shutdownDebugf("managed process kill wait timed out after SIGTERM failure pid=%d", pid) - } - result.duration = time.Since(start) - return result + shutdownDebugf("managed process graceful termination requested label=%q scope=%s root_pid=%d target_pid=%d", + p.label, scope, pid, targetPID) + if err := terminateManagedProcess(pid, targetPID, targetReady); err != nil { + return p.handleGracefulTerminationError(start, result, pid, targetPID, scope, err) } - shutdownDebugf("managed process group SIGTERM sent pgid=%d", pid) + shutdownDebugf("managed process graceful termination sent label=%q scope=%s root_pid=%d target_pid=%d", + p.label, scope, pid, targetPID) select { case <-p.done: - result.duration = time.Since(start) - result.graceful = true shutdownDebugf("managed process exited within grace pid=%d", pid) - return result + return p.finishGracefulShutdown(start, pid, result) case <-time.After(managedProcessShutdownGrace): } shutdownDebugf("managed process grace expired; sending SIGKILL pgid=%d", pid) @@ -361,6 +365,72 @@ func (p *managedProcess) kill() managedProcessShutdownResult { return result } +func (p *managedProcess) handleGracefulTerminationError(start time.Time, result managedProcessShutdownResult, pid, targetPID int, scope gracefulSignalScope, err error) managedProcessShutdownResult { + if errors.Is(err, syscall.ESRCH) { + shutdownDebugf("managed process graceful target already gone label=%q scope=%s root_pid=%d target_pid=%d", + p.label, scope, pid, targetPID) + return p.finishGracefulShutdown(start, pid, result) + } + shutdownDebugf("managed process graceful termination failed label=%q scope=%s root_pid=%d target_pid=%d err=%v; killing process", + p.label, scope, pid, targetPID, err) + shutdownDebugf("managed process SIGKILL requested label=%q pid=%d reason=%q", p.label, pid, "sigterm_failed") + result.forceKilled = true + result.err = err + if killErr := killManagedProcessGroup(pid); killErr != nil { + _ = p.cmd.Process.Kill() + result.err = errors.Join(result.err, killErr) + } + if waitForManagedProcessKillDone(p.done, managedProcessForceKillWait) { + shutdownDebugf("managed process killed after SIGTERM failure pid=%d", pid) + } else { + result.err = errors.Join(result.err, fmt.Errorf("timed out waiting for process %d after SIGKILL", pid)) + shutdownDebugf("managed process kill wait timed out after SIGTERM failure pid=%d", pid) + } + result.duration = time.Since(start) + return result +} + +func (p *managedProcess) gracefulTargetPID(rootPID int) (int, bool) { + if p.gracefulPIDFile == "" { + return rootPID, true + } + raw, err := os.ReadFile(p.gracefulPIDFile) + if err != nil { + shutdownDebugf("managed process graceful target unavailable path=%q err=%v; using tree-wide fallback", + p.gracefulPIDFile, err) + return rootPID, false + } + targetPID, err := strconv.Atoi(strings.TrimSpace(string(raw))) + if err != nil || targetPID <= 0 || !isManagedProcessTarget(rootPID, targetPID) { + shutdownDebugf("managed process graceful target invalid path=%q value=%q; using tree-wide fallback", + p.gracefulPIDFile, strings.TrimSpace(string(raw))) + return rootPID, false + } + return targetPID, true +} + +func (p *managedProcess) finishGracefulShutdown(start time.Time, pid int, result managedProcessShutdownResult) managedProcessShutdownResult { + result.duration = time.Since(start) + result.graceful = true + if !managedProcessGroupCleanupSupported() { + return result + } + if err := killManagedProcessGroup(pid); err != nil { + if errors.Is(err, syscall.ESRCH) { + shutdownDebugf("managed process descendant group already gone label=%q pid=%d", p.label, pid) + return result + } + result.forceKilled = true + result.err = err + shutdownDebugf("managed process descendant force cleanup failed label=%q pid=%d err=%v", p.label, pid, err) + return result + } + result.forceKilled = true + shutdownDebugf("managed process root exited; descendant process group force cleanup sent label=%q pgid=%d", + p.label, pid) + return result +} + func (p *managedProcess) forceKill(reason string) managedProcessShutdownResult { start := time.Now() result := managedProcessShutdownResult{label: p.label} @@ -373,10 +443,8 @@ func (p *managedProcess) forceKill(reason string) managedProcessShutdownResult { result.pid = pid select { case <-p.done: - result.duration = time.Since(start) - result.graceful = true shutdownDebugf("managed process force kill skipped; already exited label=%q pid=%d reason=%q", p.label, pid, reason) - return result + return p.finishGracefulShutdown(start, pid, result) default: } shutdownDebugf("managed process group SIGKILL requested label=%q pgid=%d reason=%q", p.label, pid, reason) diff --git a/apps/backend/internal/launcher/process_group_default.go b/apps/backend/internal/launcher/process_group_default.go index 9ef1d9dcbb..46f556696f 100644 --- a/apps/backend/internal/launcher/process_group_default.go +++ b/apps/backend/internal/launcher/process_group_default.go @@ -17,6 +17,22 @@ func killManagedProcessGroup(_ int) error { return errors.New("process groups are not supported on this platform") } +func managedProcessGracefulScope(_ bool) gracefulSignalScope { + return gracefulSignalUnsupported +} + +func terminateManagedProcess(pid, _ int, _ bool) error { + return terminateManagedProcessGroup(pid) +} + func terminateManagedProcessGroup(_ int) error { return errors.New("process groups are not supported on this platform") } + +func isManagedProcessTarget(_, _ int) bool { + return false +} + +func managedProcessGroupCleanupSupported() bool { + return false +} diff --git a/apps/backend/internal/launcher/process_group_unix.go b/apps/backend/internal/launcher/process_group_unix.go index 0dc2a3e9d5..7d428f4c58 100644 --- a/apps/backend/internal/launcher/process_group_unix.go +++ b/apps/backend/internal/launcher/process_group_unix.go @@ -20,6 +20,29 @@ func killManagedProcessGroup(pid int) error { return syscall.Kill(-pid, syscall.SIGKILL) } +func managedProcessGracefulScope(targetReady bool) gracefulSignalScope { + if targetReady { + return gracefulSignalRootOnly + } + return gracefulSignalTreeWide +} + +func terminateManagedProcess(rootPID, targetPID int, targetReady bool) error { + if targetReady { + return syscall.Kill(targetPID, syscall.SIGTERM) + } + return syscall.Kill(-rootPID, syscall.SIGTERM) +} + func terminateManagedProcessGroup(pid int) error { return syscall.Kill(-pid, syscall.SIGTERM) } + +func isManagedProcessTarget(rootPID, targetPID int) bool { + pgid, err := syscall.Getpgid(targetPID) + return err == nil && pgid == rootPID +} + +func managedProcessGroupCleanupSupported() bool { + return true +} diff --git a/apps/backend/internal/launcher/process_group_unix_test.go b/apps/backend/internal/launcher/process_group_unix_test.go index 636e8550c9..635125b1ba 100644 --- a/apps/backend/internal/launcher/process_group_unix_test.go +++ b/apps/backend/internal/launcher/process_group_unix_test.go @@ -4,10 +4,13 @@ package launcher import ( "bytes" + "errors" "os" "os/exec" "os/signal" "path/filepath" + "runtime" + "strconv" "strings" "sync" "syscall" @@ -16,6 +19,9 @@ import ( ) const launcherSignalHelperEnv = "KANDEV_LAUNCHER_SIGNAL_HELPER" +const launcherProcessTreeHelperEnv = "KANDEV_LAUNCHER_PROCESS_TREE_HELPER" +const launcherProcessTreeDescendantEnv = "KANDEV_LAUNCHER_PROCESS_TREE_DESCENDANT" +const launcherProcessTreeExitDescendantEnv = "KANDEV_LAUNCHER_PROCESS_TREE_EXIT_DESCENDANT" func TestConfigureManagedProcessCreatesProcessGroup(t *testing.T) { cmd := exec.Command("kandev") @@ -76,6 +82,117 @@ func TestManagedProcessKillSendsGracefulSignalBeforeForceKill(t *testing.T) { } } +func TestManagedProcessKillSignalsOnlyRootBeforeForceKill(t *testing.T) { + tempDir := t.TempDir() + rootReadyFile := filepath.Join(tempDir, "root-ready") + rootTermFile := filepath.Join(tempDir, "root-term") + descendantReadyFile := filepath.Join(tempDir, "descendant-ready") + descendantTermFile := filepath.Join(tempDir, "descendant-term") + descendantPIDFile := filepath.Join(tempDir, "descendant-pid") + releaseFile := filepath.Join(tempDir, "release") + cmd := exec.Command(os.Args[0], "-test.run=TestLauncherProcessTreeHelper") + cmd.Env = append(os.Environ(), + launcherProcessTreeHelperEnv+"=1", + "KANDEV_LAUNCHER_PROCESS_TREE_ROOT_READY_FILE="+rootReadyFile, + "KANDEV_LAUNCHER_PROCESS_TREE_ROOT_TERM_FILE="+rootTermFile, + "KANDEV_LAUNCHER_PROCESS_TREE_DESCENDANT_READY_FILE="+descendantReadyFile, + "KANDEV_LAUNCHER_PROCESS_TREE_DESCENDANT_TERM_FILE="+descendantTermFile, + "KANDEV_LAUNCHER_PROCESS_TREE_DESCENDANT_PID_FILE="+descendantPIDFile, + "KANDEV_LAUNCHER_PROCESS_TREE_RELEASE_FILE="+releaseFile, + ) + configureManagedProcess(cmd) + if err := cmd.Start(); err != nil { + t.Fatalf("start process-tree fixture: %v", err) + } + proc := &managedProcess{label: "process-tree-fixture", cmd: cmd, done: make(chan struct{})} + go waitForManagedProcess(t, proc) + t.Cleanup(func() { + _ = killManagedProcessGroup(cmd.Process.Pid) + if exited, _ := proc.Exited(); !exited { + waitForManagedProcessDone(t, proc, 5*time.Second) + } + }) + + waitForFile(t, rootReadyFile) + killDone := make(chan managedProcessShutdownResult, 1) + go func() { + killDone <- proc.kill() + }() + waitForFile(t, rootTermFile) + if fileAppears(t, descendantTermFile, 500*time.Millisecond) { + t.Fatalf("descendant received the launcher's initial graceful signal") + } + if err := cmd.Process.Signal(syscall.SIGUSR1); err != nil { + t.Fatalf("release root fixture: %v", err) + } + result := <-killDone + if !result.graceful || !result.forceKilled { + t.Fatalf("kill result graceful=%v forceKilled=%v err=%v, want true/true/nil", + result.graceful, result.forceKilled, result.err) + } + if exited, exitCode := proc.Exited(); !exited || exitCode != 0 { + t.Fatalf("process-tree fixture exit status = exited:%v code:%d, want true/0", exited, exitCode) + } + descendantPID := readProcessPID(t, descendantPIDFile) + waitForProcessGone(t, descendantPID, 5*time.Second) +} + +func TestManagedProcessKillTargetsBackendPIDFile(t *testing.T) { + tempDir := t.TempDir() + rootReadyFile := filepath.Join(tempDir, "root-ready") + rootTermFile := filepath.Join(tempDir, "root-term") + descendantReadyFile := filepath.Join(tempDir, "descendant-ready") + descendantTermFile := filepath.Join(tempDir, "descendant-term") + descendantPIDFile := filepath.Join(tempDir, "descendant-pid") + releaseFile := filepath.Join(tempDir, "release") + cmd := exec.Command(os.Args[0], "-test.run=TestLauncherProcessTreeHelper") + cmd.Env = append(os.Environ(), + launcherProcessTreeHelperEnv+"=1", + launcherProcessTreeExitDescendantEnv+"=1", + "KANDEV_LAUNCHER_PROCESS_TREE_ROOT_READY_FILE="+rootReadyFile, + "KANDEV_LAUNCHER_PROCESS_TREE_ROOT_TERM_FILE="+rootTermFile, + "KANDEV_LAUNCHER_PROCESS_TREE_DESCENDANT_READY_FILE="+descendantReadyFile, + "KANDEV_LAUNCHER_PROCESS_TREE_DESCENDANT_TERM_FILE="+descendantTermFile, + "KANDEV_LAUNCHER_PROCESS_TREE_DESCENDANT_PID_FILE="+descendantPIDFile, + "KANDEV_LAUNCHER_PROCESS_TREE_RELEASE_FILE="+releaseFile, + ) + configureManagedProcess(cmd) + if err := cmd.Start(); err != nil { + t.Fatalf("start process-tree fixture: %v", err) + } + proc := &managedProcess{ + label: "process-tree-pid-file-fixture", + cmd: cmd, + gracefulPIDFile: descendantPIDFile, + done: make(chan struct{}), + } + go waitForManagedProcess(t, proc) + t.Cleanup(func() { + _ = killManagedProcessGroup(cmd.Process.Pid) + if exited, _ := proc.Exited(); !exited { + waitForManagedProcessDone(t, proc, 5*time.Second) + } + }) + + waitForFile(t, rootReadyFile) + killDone := make(chan managedProcessShutdownResult, 1) + go func() { + killDone <- proc.kill() + }() + waitForFile(t, descendantTermFile) + if fileAppears(t, rootTermFile, 500*time.Millisecond) { + t.Fatalf("launcher signalled the wrapper instead of the backend PID from the file") + } + if err := cmd.Process.Signal(syscall.SIGUSR1); err != nil { + t.Fatalf("release root fixture: %v", err) + } + result := <-killDone + if !result.graceful || result.err != nil { + t.Fatalf("kill result graceful=%v forceKilled=%v err=%v, want graceful without error", + result.graceful, result.forceKilled, result.err) + } +} + func TestAttachSignalsSingleSignalGracefulShutdown(t *testing.T) { tempDir := t.TempDir() termFile := filepath.Join(tempDir, "term") @@ -148,6 +265,86 @@ func TestLauncherSignalHelper(t *testing.T) { os.Exit(0) } +func TestLauncherProcessTreeHelper(t *testing.T) { + if os.Getenv(launcherProcessTreeHelperEnv) != "1" { + return + } + descendantReadyFile := os.Getenv("KANDEV_LAUNCHER_PROCESS_TREE_DESCENDANT_READY_FILE") + descendantTermFile := os.Getenv("KANDEV_LAUNCHER_PROCESS_TREE_DESCENDANT_TERM_FILE") + descendantPIDFile := os.Getenv("KANDEV_LAUNCHER_PROCESS_TREE_DESCENDANT_PID_FILE") + rootReadyFile := os.Getenv("KANDEV_LAUNCHER_PROCESS_TREE_ROOT_READY_FILE") + rootTermFile := os.Getenv("KANDEV_LAUNCHER_PROCESS_TREE_ROOT_TERM_FILE") + releaseFile := os.Getenv("KANDEV_LAUNCHER_PROCESS_TREE_RELEASE_FILE") + descendant := exec.Command(os.Args[0], "-test.run=TestLauncherProcessTreeDescendantHelper") + descendant.Env = append(os.Environ(), + launcherProcessTreeDescendantEnv+"=1", + "KANDEV_LAUNCHER_PROCESS_TREE_DESCENDANT_READY_FILE="+descendantReadyFile, + "KANDEV_LAUNCHER_PROCESS_TREE_DESCENDANT_TERM_FILE="+descendantTermFile, + ) + if err := descendant.Start(); err != nil { + t.Fatalf("start descendant fixture: %v", err) + } + descendantReleased := false + t.Cleanup(func() { + if descendantReleased { + return + } + _ = descendant.Process.Kill() + _ = descendant.Wait() + }) + if err := os.WriteFile(descendantPIDFile, []byte(strconv.Itoa(descendant.Process.Pid)), 0o600); err != nil { + t.Fatalf("write descendant pid file: %v", err) + } + waitForFile(t, descendantReadyFile) + if err := os.WriteFile(rootReadyFile, []byte("ready"), 0o600); err != nil { + t.Fatalf("write root ready file: %v", err) + } + signals := make(chan os.Signal, 1) + signal.Notify(signals, syscall.SIGTERM, syscall.SIGUSR1) + defer signal.Stop(signals) + if got := <-signals; got != syscall.SIGTERM { + t.Fatalf("root received signal %v, want SIGTERM", got) + } + if err := os.WriteFile(rootTermFile, []byte("term"), 0o600); err != nil { + t.Fatalf("write root term file: %v", err) + } + for { + if _, err := os.Stat(releaseFile); err == nil { + break + } + if got := <-signals; got == syscall.SIGUSR1 { + if err := os.WriteFile(releaseFile, []byte("release"), 0o600); err != nil { + t.Fatalf("write release file: %v", err) + } + } + } + descendantReleased = true +} + +func TestLauncherProcessTreeDescendantHelper(t *testing.T) { + if os.Getenv(launcherProcessTreeDescendantEnv) != "1" { + return + } + readyFile := os.Getenv("KANDEV_LAUNCHER_PROCESS_TREE_DESCENDANT_READY_FILE") + termFile := os.Getenv("KANDEV_LAUNCHER_PROCESS_TREE_DESCENDANT_TERM_FILE") + if err := os.WriteFile(readyFile, []byte("ready"), 0o600); err != nil { + t.Fatalf("write descendant ready file: %v", err) + } + signals := make(chan os.Signal, 1) + signal.Notify(signals, syscall.SIGTERM) + defer signal.Stop(signals) + for got := range signals { + if got == syscall.SIGTERM { + if err := os.WriteFile(termFile, []byte("term"), 0o600); err != nil { + t.Fatalf("write descendant term file: %v", err) + } + if os.Getenv(launcherProcessTreeExitDescendantEnv) == "1" { + return + } + } + } +} + func startManagedSignalHelper(t *testing.T, termFile string, mode string) *managedProcess { t.Helper() readyFile := filepath.Join(t.TempDir(), "ready") @@ -267,7 +464,7 @@ func (o *safeOutput) String() string { func waitForFile(t *testing.T, path string) { t.Helper() - for range 100 { + for range 500 { if _, err := os.Stat(path); err == nil { return } @@ -275,3 +472,64 @@ func waitForFile(t *testing.T, path string) { } t.Fatalf("timed out waiting for %s", path) } + +func fileAppears(t *testing.T, path string, timeout time.Duration) bool { + t.Helper() + deadline := time.Now().Add(timeout) + for time.Now().Before(deadline) { + if _, err := os.Stat(path); err == nil { + return true + } + time.Sleep(10 * time.Millisecond) + } + return false +} + +func waitForManagedProcess(t *testing.T, proc *managedProcess) { + t.Helper() + err := proc.cmd.Wait() + code := 0 + if err != nil { + code = 1 + if exitErr, ok := err.(*exec.ExitError); ok { + code = exitErr.ExitCode() + } + } + proc.mu.Lock() + proc.exitCode = code + proc.exited = true + proc.mu.Unlock() + close(proc.done) +} + +func readProcessPID(t *testing.T, path string) int { + t.Helper() + raw, err := os.ReadFile(path) + if err != nil { + t.Fatalf("read process pid file: %v", err) + } + pid, err := strconv.Atoi(strings.TrimSpace(string(raw))) + if err != nil { + t.Fatalf("parse process pid %q: %v", string(raw), err) + } + return pid +} + +func waitForProcessGone(t *testing.T, pid int, timeout time.Duration) { + t.Helper() + deadline := time.Now().Add(timeout) + for time.Now().Before(deadline) { + if runtime.GOOS == "linux" { + status, err := os.ReadFile(filepath.Join("/proc", strconv.Itoa(pid), "status")) + if errors.Is(err, os.ErrNotExist) || strings.Contains(string(status), "State:\tZ") { + return + } + } + process, err := os.FindProcess(pid) + if err != nil || process.Signal(syscall.Signal(0)) != nil { + return + } + time.Sleep(10 * time.Millisecond) + } + t.Fatalf("process pid=%d remained alive", pid) +} diff --git a/apps/backend/internal/launcher/process_group_windows.go b/apps/backend/internal/launcher/process_group_windows.go index 67c5580018..34fce3025d 100644 --- a/apps/backend/internal/launcher/process_group_windows.go +++ b/apps/backend/internal/launcher/process_group_windows.go @@ -23,10 +23,28 @@ func killManagedProcessGroup(pid int) error { return runLauncherTaskkill("/F", "/T", "/PID", fmt.Sprintf("%d", pid)) } +func managedProcessGracefulScope(_ bool) gracefulSignalScope { + return gracefulSignalTreeWide +} + +func terminateManagedProcess(pid, _ int, _ bool) error { + // The dev backend is launched through make on Windows. Signalling only make + // would orphan the backend, so retain tree-wide graceful cleanup there. + return terminateManagedProcessGroup(pid) +} + func terminateManagedProcessGroup(pid int) error { return runLauncherTaskkill("/T", "/PID", fmt.Sprintf("%d", pid)) } +func isManagedProcessTarget(_, _ int) bool { + return false +} + +func managedProcessGroupCleanupSupported() bool { + return true +} + func runLauncherTaskkill(args ...string) error { return winproc.RunTaskkill(args...) } diff --git a/docs/plans/shutdown-plugin-process-group-teardown/plan.md b/docs/plans/shutdown-plugin-process-group-teardown/plan.md new file mode 100644 index 0000000000..ad19c6d74b --- /dev/null +++ b/docs/plans/shutdown-plugin-process-group-teardown/plan.md @@ -0,0 +1,137 @@ +--- +spec: docs/specs/shutdown-log-noise/spec.md +created: 2026-08-13 +status: done +--- + +# Implementation Plan: Let plugin cleanup run before launcher force kill + +## Overview + +Change the launcher’s graceful child shutdown so its first signal targets only +the supervised root process on platforms where that is safe. Unix dev runs +through a make wrapper, so the backend writes its actual PID to a launcher-owned +file and the launcher targets that validated same-process-group child. Keep +process-group termination for the existing grace-expiry and second-signal force +paths, plus the existing tree-wide graceful fallback on platforms with wrapper +processes that could otherwise be orphaned. Force cleanup also runs after the +root exits so remaining descendants are not leaked. The existing go-plugin +adapter already has the correct severity policy: expected deliberate +termination is DEBUG, while an unexpected plugin exit remains ERROR. The +launcher change makes that policy reachable before a plugin is killed directly +by the parent’s process-group signal. + +## Confirmed root cause + +The launcher creates a separate process group for each supervised child and +currently sends SIGTERM to the entire group from +`apps/backend/internal/launcher/process.go`. Backend-owned plugin subprocesses +inherit that group. On Ctrl+C they therefore receive SIGTERM at the same time as +the backend, before `runtime.Manager.StopAll` calls `hcProcess.Kill` and sets +the adapter’s intentional-stop flag. Hashicorp go-plugin then logs +`plugin process exited ... error="signal: terminated"` at ERROR. The backend +still reports `Graceful shutdown complete` with `error_count: 0`, so the +observed plugin lines are misleading teardown noise rather than plugin +failures. + +## Backend + +### Launcher graceful signal boundary + +Modify `apps/backend/internal/launcher/process.go` and the platform helpers in +`apps/backend/internal/launcher/process_group_{unix,windows,default}.go`: + +- Add a platform-specific root-only graceful termination helper. +- Make `managedProcess.kill` use the root-only helper for its first signal, + resolving the backend PID handoff for Unix dev wrappers. +- Retain `killManagedProcessGroup` for the existing grace-expiry and + second-signal force paths. +- Run process-group force cleanup after a root exits before descendants, and + retain the unsupported-platform limitation where no portable group cleanup + exists. +- Update shutdown debug messages and error handling to distinguish root-only + graceful signaling from process-group force cleanup. +- Preserve the existing 75-second grace duration, second-signal behavior, + result summaries, child exit-code handling, and process-group setup. + +The platform helper must preserve the launcher contract on Unix, Windows, and +unsupported platforms. On Windows, the implementation must account for the +existing `make -C apps/backend dev` wrapper rather than leaving the backend +child orphaned when only the wrapper receives the graceful signal, so Windows +retains tree-wide graceful termination. If the platform cannot provide a safe +root-only signal or portable descendant cleanup, retain the available fallback +and document that limitation instead of claiming a complete-tree guarantee. + +### Plugin log-level policy + +Do not broadly downgrade all plugin exits. Keep +`apps/backend/internal/plugins/runtime/hclog_adapter.go` unchanged unless the +implementation demonstrates that an intentional runtime kill still reaches +ERROR after the launcher sequencing fix. The required policy is: + +- deliberate shutdown termination (`signal: terminated` or `signal: killed`) + is DEBUG/no ERROR; +- an unexpected plugin exit while the runtime is active remains ERROR in the + go-plugin adapter and WARN in the runtime supervisor’s existing unexpected + exit path. + +## Tests + +1. **Root-only graceful signal.** Extend + `apps/backend/internal/launcher/process_group_unix_test.go` with a helper + process that starts a descendant in the same process group. Assert that + `managedProcess.kill` lets the root handle SIGTERM and exit while the + descendant does not receive the initial graceful signal. Clean up the + descendant through the existing process-group force helper. +2. **Backend PID handoff.** Exercise a managed Unix wrapper whose PID file + names an in-group backend child. Assert that the launcher signals that + child, not the wrapper, and still completes shutdown without an error. +3. **Force cleanup remains tree-wide.** Keep or extend the existing second + signal/force-kill coverage to assert that a descendant that ignores the + graceful phase is reaped by process-group force cleanup, including after + the root exits. +4. **Plugin severity regression.** Re-run the existing focused adapter tests in + `apps/backend/internal/plugins/runtime/hclog_adapter_test.go`; add a test + only if the launcher/runtime integration exposes a new failure mode. Assert + that deliberate termination is DEBUG and an unexpected exit remains ERROR. + +## Verification Results + +- Root-only graceful signaling and post-root descendant cleanup regressions + passed under `go test -race`. +- Backend PID handoff writer and Unix wrapper-target regression passed. +- Existing second-signal force-shutdown coverage passed. +- Plugin adapter severity coverage passed all six focused tests. +- `go test ./internal/launcher ./internal/plugins/runtime` passed. +- Windows launcher and backend packages cross-compiled successfully with + `GOOS=windows GOARCH=amd64 go test -c`. +- `golangci-lint run ./internal/launcher ./cmd/kandev --timeout=5m` passed + (0 issues). +- `git diff --check` passed. + +The plugin adapter required no additional log-level change. Unix and Darwin +now signal the supervised root first, or the backend PID under the Unix dev +make wrapper. Windows keeps tree-wide graceful termination because the make +wrapper makes root-only signaling unsafe. Process-group force cleanup also +runs after root exit where supported; unsupported platforms retain their +available root cleanup behavior. + +## Implementation Waves And Parallel Candidates + +Wave 1, sequential: + +- [x] [task-01-launcher-graceful-signal](task-01-launcher-graceful-signal.md) + +The task is sequential because the launcher implementation, platform helpers, +process-group integration tests, and plugin severity verification share the +same shutdown boundary. + +## Risks + +- A root-only signal must not orphan the `make` wrapper or Vite child on + Windows. Windows retains the documented tree-wide graceful fallback, while + Unix dev targets the backend PID handoff. +- Changing the first signal must not weaken the existing second-signal or + grace-expiry force cleanup. +- No task/session state, WS response, plugin restart policy, or grace timeout + change is intended. diff --git a/docs/plans/shutdown-plugin-process-group-teardown/task-01-launcher-graceful-signal.md b/docs/plans/shutdown-plugin-process-group-teardown/task-01-launcher-graceful-signal.md new file mode 100644 index 0000000000..332875c668 --- /dev/null +++ b/docs/plans/shutdown-plugin-process-group-teardown/task-01-launcher-graceful-signal.md @@ -0,0 +1,98 @@ +--- +id: "01-launcher-graceful-signal" +title: "Signal launcher roots before force cleanup" +status: done +wave: 1 +depends_on: [] +plan: "plan.md" +spec: "../../specs/shutdown-log-noise/spec.md" +parallelism: sequential +--- + +# Task 01: Signal launcher roots before force cleanup + +## Intent + +Prevent Ctrl+C from directly terminating backend-owned plugin processes before +the backend can run its plugin cleanup. On platforms with safe root-only +signaling, the first graceful signal targets the supervised root process. The +existing process-group force path remains the fallback for grace expiry and +repeated interrupts; platforms with unsafe wrapper processes retain the +tree-wide graceful fallback. + +## Acceptance + +- On supported platforms, `managedProcess.kill` sends the first graceful + termination signal only to the supervised root process. For the Unix dev + make wrapper, it targets the backend PID written by the backend binary. A + remaining descendant in the same process group is not directly signalled + during that phase. +- If graceful shutdown does not complete before the existing grace period, or + the launcher receives a second signal, process-group force cleanup still + terminates the complete supervised tree, including descendants after root + exit, where process-group support is available. +- The existing plugin adapter policy remains conservative: deliberate plugin + termination is not logged at ERROR, while an unexpected active-runtime exit + remains visible at ERROR/WARN through the existing paths. No broad log-level + suppression is added. +- No change occurs to shutdown timeout, exit-code mapping, plugin lifecycle or + restart policy, task/session state, or WS responses. + +## Verification + +From the repository root: + +```bash +cd apps/backend && go test ./internal/launcher ./internal/plugins/runtime +``` + +If platform-specific launcher tests are unavailable on the current host, run +the available Unix/Linux package tests and record the unverified platform in +`## Results`. + +## Files likely touched + +- `apps/backend/internal/launcher/process.go` +- `apps/backend/internal/launcher/process_group_unix.go` +- `apps/backend/internal/launcher/process_group_windows.go` +- `apps/backend/internal/launcher/process_group_default.go` +- `apps/backend/internal/launcher/process_group_unix_test.go` +- `apps/backend/internal/launcher/process_group_windows_test.go` (if needed) +- `apps/backend/cmd/kandev/main.go` and `main_test.go` +- `apps/backend/internal/plugins/runtime/hclog_adapter.go` and its test only + if focused verification proves the existing policy is still bypassed + +## Dependencies and risks + +No external dependencies. The main platform risk is preserving descendant +cleanup on Windows, where the dev backend is launched through `make` without a +POSIX `exec`; the implementation therefore retains Windows tree-wide graceful +termination. + +## Results + +- `go test -race ./internal/launcher -run + 'TestManagedProcessKillSignalsOnlyRootBeforeForceKill|TestAttachSignalsSecondSignalForceKillsChildren' -count=1` + passed, including descendant cleanup after root exit. +- `go test ./internal/launcher -run + 'TestManagedProcessKill(SignalsOnlyRootBeforeForceKill|TargetsBackendPIDFile)$' -count=1` + passed (2 tests). +- `go test ./cmd/kandev -run '^TestDispatchWritesBackendPIDFile$' -count=1` + passed. +- The process-tree assertion treats a reaped Linux zombie as terminated, which + avoids false leak failures while container init reaps force-killed children. +- `go test ./internal/plugins/runtime -run '^TestHCLogAdapter' -count=1` + passed (6 tests). +- `go test ./internal/launcher ./internal/plugins/runtime` passed (227 tests). +- `GOOS=windows GOARCH=amd64 go test -c` passed for `./internal/launcher` and + `./cmd/kandev`. +- `golangci-lint run ./internal/launcher ./cmd/kandev --timeout=5m` passed + (0 issues). +- `git diff --check` passed. + +Unix and Darwin use root-only graceful signaling, with the Unix dev make +wrapper targeting the backend PID handoff. Windows retains the existing +tree-wide graceful fallback because signaling only that wrapper could orphan +descendants. Process-group cleanup runs after root exit on supported platforms. +The plugin adapter was not modified: its existing DEBUG-for-deliberate-stop and +ERROR-for-unexpected-exit policy passed the focused tests. diff --git a/docs/specs/shutdown-log-noise/spec.md b/docs/specs/shutdown-log-noise/spec.md index 15596cb2e5..4e93dfa4be 100644 --- a/docs/specs/shutdown-log-noise/spec.md +++ b/docs/specs/shutdown-log-noise/spec.md @@ -25,8 +25,24 @@ the stack traces suggest a crash where none occurred. - The go-plugin subprocess exiting because Kandev killed it during shutdown SHALL NOT surface as a library ERROR (`plugin process exited ... signal: terminated`). -- No change to control flow, task/session state transitions, returned errors, - or WS responses. This is a logging-severity change only. +- On platforms where the supervised root can be signaled without orphaning a + wrapper's descendants, the launcher SHALL deliver the first + graceful-shutdown signal only to that root. This gives the backend and its + owned runtimes, including plugins, an opportunity to run their cleanup paths + before forced descendant cleanup. For the Unix dev wrapper, the launcher + SHALL target the backend PID written by the backend binary and validate that + it remains in the wrapper's process group. If that target is unavailable, or + root-only signaling is unsafe for a platform's wrapper process, the launcher + SHALL retain its tree-wide graceful fallback so descendants are not orphaned. + On platforms with process-group support, the complete shutdown MUST still + terminate the supervised process tree, including descendants left after the + root exits. Platforms without portable process-group support only guarantee + cleanup through their available supervised-root operation. +- No change to backend/plugin lifecycle control flow, task/session state + transitions, returned errors, or WS responses. Launcher sequencing changes + only at the graceful-signal versus forced-cleanup boundary, so the complete + supervised process tree still terminates on platforms with process-group + support. ## Affected log sites and target behavior Classification reuses existing helpers/sentinels wherever possible. @@ -48,8 +64,18 @@ Classification reuses existing helpers/sentinels wherever possible. 3. `internal/plugins/runtime/manager.go` (`hcplugin.NewClient`, L394). go-plugin is constructed with no `Logger`, so its default hclog logger prints the process exit at ERROR when `client.Kill()` runs during `StopAll`. Supply an - hclog logger routed through Kandev's logger and silence it for the - deliberate kill so an expected `signal: terminated` is not an ERROR. + hclog logger routed through Kandev's logger and downgrade the deliberate + kill so an expected `signal: terminated` is not an ERROR. The launcher must + signal the supervised backend root first; otherwise a process-group + SIGTERM reaches the plugin before this intentional-stop marker is set. +4. `internal/launcher/process.go` graceful child shutdown. On platforms with a + safe root-only signal, the first signal SHALL target only the supervised + root process. The Unix dev wrapper SHALL use the backend PID handoff for + this target. If the root does not exit within the existing grace period, or + a second interrupt arrives, the launcher SHALL use process-group force + cleanup to reap the complete tree, including descendants after root exit. + Platforms with an unsafe wrapper process SHALL use the existing tree-wide + graceful fallback. ## Log sites reviewed and deliberately left unchanged - `internal/agent/runtime/lifecycle/manager_events.go:544` "agent updates @@ -90,9 +116,24 @@ Classification reuses existing helpers/sentinels wherever possible. - **GIVEN** the plugin manager `StopAll` kills a running plugin during shutdown, **WHEN** the subprocess exits with `signal: terminated`, **THEN** no ERROR log line for that expected exit is emitted. +- **GIVEN** a supervised backend has plugin subprocesses in the same process + group, **WHEN** the launcher receives the first Ctrl+C, **THEN** it signals + the backend root first on platforms with safe root-only signaling, using the + backend PID handoff when the managed process is a Unix dev wrapper. The + backend can invoke plugin cleanup, and the plugin subprocesses are not + directly terminated by the launcher's initial graceful signal. Platforms + with an unsafe wrapper use the existing tree-wide graceful fallback. +- **GIVEN** the supervised root ignores the graceful signal or a second Ctrl+C + arrives, **WHEN** the launcher's grace/force path runs, **THEN** the existing + process-group force cleanup terminates the root and all descendants, even if + the root exits before a descendant does. ## Out of scope -- Changing shutdown ordering, timeouts, or which subprocesses are killed. +- Changing the existing grace duration or second-signal force-kill policy. +- Changing which processes the final forced cleanup terminates; on platforms + with process-group support, the complete supervised process tree remains + covered by process-group force cleanup. Unsupported platforms retain their + existing root-only limitation. - Changing WS responses or task/session state on launch failure. - Suppressing agentctl child stderr relay during shutdown. - Any non-shutdown logging severity review.