The deploy that hung for an hour

A deploy would sit with no new log lines, and then, exactly an hour after it started, fail on the control plane with GRPC::DeadlineExceeded. The agent had its own 20-minute build timeout, and that timeout was firing. Nothing was stopping.

Most of what Railyard’s agent does is start other programs. A deploy is git, then docker build, then a release command in a throwaway container, then docker run, each one a child process whose output streams back to the dashboard line by line. This week I fixed two bugs about the end of a process’s life: stopping it, and what it leaves behind.

A 20-minute timeout that took 60

The hour is the deadline the control plane puts on the whole deploy call to the agent. It’s meant to be a backstop that never fires. Inside it, the agent runs each build under a shorter context. At the time that was 20 minutes, after which a wedged build (a stuck bundle install, a yarn waiting on a dead registry) should be killed and reported as Build exceeded 20m0s and was stopped. Meanwhile every deploy queued behind the stuck one waited too.

To see why the 20 minutes didn’t hold you need two pieces of Unix.

A pipe is a small kernel buffer with two ends. One process writes into one end, another reads from the other. Go’s cmd.StdoutPipe() creates one and hands the write end to the child as its standard output. The reader sees end-of-file only when every copy of the write end has been closed. Copies are easy to make: when a process starts a child, the child inherits its open file descriptors by default, stdout and stderr included. If your child starts a grandchild, the grandchild holds the same write end, and the pipe stays open until it exits too.

A process group is the kernel’s name for “this process and the things it started”. Every process belongs to one, identified by a process group ID. A child joins its parent’s group by default. A process can be started as the leader of a new group whose ID equals its own PID, and its descendants then inherit that group. Sending a signal to a negative PID sends it to every process in the group with that ID. That is how your shell stops a whole pipeline when you press Ctrl-C.

The build command was never one process. On a server short on memory, the agent wraps the build in systemd-run to cap its memory, then nice and ionice so it doesn’t starve the apps already running there, then docker. The docker CLI doesn’t do the build itself either: it hands build to the buildx plugin, a separate program started as a child with the same stdout and stderr.

exec.CommandContext ties a process to a context, and when the context expires, Go kills the process. One process. Its default cancel is cmd.Process.Kill(), which sends SIGKILL to the direct child and nothing else. At 20 minutes the wrapper died, and the processes below it, buildx among them, kept running with the pipe open. The goroutines reading stdout and stderr kept waiting for an EOF that never came, the channel they fed never closed, the loop that forwarded lines to the control plane never ended, and cmd.Wait() was never reached. The agent held the deploy stream open, doing nothing, until the control plane’s hour ran out.

Killing the whole group

Here is how the agent runs a step now, minus error handling. The first three lines after CommandContext and the helper at the bottom are the fix:

cmd := exec.CommandContext(ctx, name, args...)
cmd.SysProcAttr = &syscall.SysProcAttr{Setpgid: true}
cmd.Cancel = func() error { return killProcessGroup(cmd) }
cmd.WaitDelay = 10 * time.Second

stdout, _ := cmd.StdoutPipe()
stderr, _ := cmd.StderrPipe()
cmd.Start()

events := scanLines(stdout, stderr) // closed when both pipes reach EOF
for ev := range events {
	if err := stream.Send(ev); err != nil {
		killProcessGroup(cmd)
		return fmt.Errorf("stream send: %w", err)
	}
}
return cmd.Wait()

func killProcessGroup(cmd *exec.Cmd) error {
	if err := syscall.Kill(-cmd.Process.Pid, syscall.SIGKILL); err != nil {
		return cmd.Process.Kill()
	}
	return nil
}

Setpgid: true starts each step as the leader of its own group, so the step and everything under it share one group ID, and none of it shares a group with the agent. That second part matters: without it, killing the step’s group would mean killing the agent’s own group. cmd.Cancel is the hook exec.CommandContext calls when the context is done, and I replaced its default with a SIGKILL to -pid, the whole group. If that fails it falls back to the single-process kill. The same helper runs when sending to the deploy stream fails, because a control plane that went away is also a reason to stop building.

When every process in the group dies, the kernel closes their copies of the pipe, the readers get EOF, the channel closes, and Wait returns. A wedged build now stops at its own timeout with a message that says so, and the deploys behind it move.

What WaitDelay does and doesn’t do

WaitDelay arrived in Go 1.20 and I added it in the same change. I read the os/exec source to know what I was relying on.

The timer starts when the context is done or when Wait sees the child exit, whichever comes first. When it expires, Go kills the child with Process.Kill if it’s still running, which is again the direct child only. Then it closes the I/O pipes it owns. Those are the pipes Go creates when you set cmd.Stdout to an io.Writer and let its own goroutines do the copying. The read end returned by StdoutPipe is in a different list: Wait closes it after the process exits.

So in my code, WaitDelay cannot unblock my scanner goroutines. They are reading from StdoutPipe, and Wait isn’t called until they finish. The group kill is what makes the pipe close. What WaitDelay adds is a bound on Wait itself: once the readers are done, Wait can’t hang for more than ten seconds on a child that ignored its signal. It’s the second guard, and it would not have prevented this bug alone.

If I had handed exec a line-splitting io.Writer instead of using StdoutPipe, WaitDelay would have closed the pipes after ten seconds and the deploy would have failed on time. The grandchild would still have been running, holding a build’s worth of memory and CPU on a server that also serves traffic. Killing the group is the fix for the cause. WaitDelay only shortens the symptom.

A process group has a known edge. Membership is voluntary: a descendant that calls setsid or setpgid leaves the group and escapes the kill. The strict tool for “everything this step started” is a cgroup, which tracks every descendant whatever its process group or session, and which cgroup v2 can kill as a unit by writing to cgroup.kill. On memory-capped servers the build already runs inside a transient systemd scope, which is a cgroup. Giving every step its own cgroup and killing that on timeout is the next piece of work here.

A pidfile that outlived its server

The second bug started with a fix I made on 13 September.

That day I deployed Lobsters, unmodified, and watched it crash-loop. Puma booted, logged Listening on http://0.0.0.0:3000, and died a moment later. Its config/puma.rb reads the pidfile path from PIDFILE, and in production falls back to /home/deploy/lobsters/shared/tmp/pids/puma.pid. That path comes from Capistrano-style deploys, where each release lives in its own directory beside a shared one. Lots of Rails apps still carry a version of it. In a container the directory doesn’t exist, so Puma crashes writing its pidfile.

Since the config already honours PIDFILE, the agent sets it for Rails apps that haven’t:

func ensurePidfileEnv(workdir string, env map[string]string) {
	if v, ok := env["PIDFILE"]; ok && strings.TrimSpace(v) != "" {
		return // the app chose its own path
	}
	if _, err := os.Stat(filepath.Join(workdir, "config", "environment.rb")); err != nil {
		return // not a Rails app
	}
	env["PIDFILE"] = "/tmp/puma.pid"
}

For an app that doesn’t read the variable it does nothing. Lobsters went from crash-looping to serving pages.

This week the Docker daemon on my development machine restarted, and two open-source Rails apps I had deployed there, Tracks and alonetone, came back in a crash loop. Their logs said A server is already running (pid: 1, file: /tmp/puma.pid).

A pidfile records the PID of a running server so tools can find it, and so a second copy doesn’t start on top of the first. A server that shuts down cleanly deletes its pidfile on the way out. When the Docker daemon goes down with containers running, they get SIGKILL and no way out, so the file stays. On boot, rails server runs a check it inherits from Rack, which amounts to this:

def check_pid!
  return unless File.exist?(pidfile)

  pid = File.read(pidfile).to_i
  raise Errno::ESRCH if pid == 0
  Process.kill(0, pid) # signal 0: "does this process exist?"
  warn "A server is already running (pid: #{pid}, file: #{pidfile})."
  exit(1)
rescue Errno::ESRCH
  File.delete(pidfile) # stale file, safe to remove
end

The stale file said 1. Inside a container, PID 1 always exists: it is the container’s main process, which here was the server doing the checking. So it concluded another server was running and exited. Docker’s unless-stopped policy started it again, it found the same file, and exited again.

Why docker restart couldn’t help

A container’s filesystem is the image’s read-only layers with one writable layer on top. Everything the app writes, /tmp included, goes into that writable layer, and the layer lives as long as the container. docker restart stops and starts the same container, so it brings back the same layer and the same stale file. The restart policy does the same. The dashboard’s Restart button called docker restart, which made it useless in exactly the case where someone would press it. The only way out was a full redeploy.

The fix is to recreate the container when a restart doesn’t take. A new container gets a fresh writable layer from the image, and the pidfile is gone. The agent doesn’t have the original deploy request at that point, so it rebuilds the docker run arguments from the container’s own docker inspect:

func recreateFromInspect(ctx context.Context, name string) error {
	out, err := exec.CommandContext(ctx, "docker", "inspect", name).Output()
	if err != nil {
		return err
	}
	var specs []inspectSpec
	if err := json.Unmarshal(out, &specs); err != nil || len(specs) == 0 {
		return fmt.Errorf("inspect %s: %v", name, err)
	}
	// image, env, entrypoint and cmd, port bindings, mounts,
	// labels (which carry the routing), memory/CPU limits, restart policy
	args := runArgs(name, specs[0])

	if err := exec.CommandContext(ctx, "docker", "rm", "-f", name).Run(); err != nil {
		return err
	}
	return exec.CommandContext(ctx, "docker", args...).Run()
}

Deciding when a restart didn’t take was the subtle part. A crash-looping container reports running for a second at a time between deaths. The signal I used is RestartCount, which Docker increments only when the restart policy restarts a container, never when you call docker restart yourself. The agent records the count, restarts, and polls status and count once a second for a few seconds. My first version only judged the last sample, and live testing caught it: that sample landed in a one-second running flicker, and the agent declared a crash-looping container healthy. Any bad sample in the window now counts.

I tested it against a container I had wedged the same way on purpose, its restart count at 13 and climbing. The Restart button recreated it, Puma booted clean, the routing labels came through, and requests reached the app again.

The stale file was at /tmp/puma.pid because my own fix had put it there. Before that, these apps wrote their pidfiles to other paths in the same writable layer, which a daemon restart would have left behind just the same. The recreate copies only what docker inspect exposes and what I chose to map, and it reattaches the container to a single network, so a container on two networks would come back on one.

Mounting /tmp as a tmpfs would empty it on every start and stop stale pidfiles before they exist. It would also surprise an app that writes something there and expects it after a restart, and I haven’t measured how many do that. Until I have, the Restart button recreates the container when it has to.