A scheduled Go container job buffers its slog output and calls log.Fatal on failure. Why is the tail of its log missing?

seniormust knowfreq 47%

answer

the last record is the one you wanted
log.Fatal is a print plus os.Exit
who runs your deferred functions?
the buffer never left the process
test it in a child process, not in-process

basics

~20 s

log.Fatal ends the process through os.Exit, which runs no deferred functions, so the deferred Flush on the buffered writer never happens and every record still in the buffer is discarded. Stop buffering the log sink, or flush before exiting.

solid answer

~40 s

log.Fatalf is a print followed by os.Exit(1), and os.Exit terminates the process immediately without running deferred functions. The defer w.Flush() that was supposed to drain the bufio.Writer never runs, so up to a bufferful of the newest records — including the ones describing the failure — die with the process. The collector is not dropping anything; those bytes never reached a file descriptor. The fix I would make first is to remove the buffer and let the handler write straight to os.Stdout, so each record is out of the process the moment Handle returns. If buffering has to stay, ban log.Fatal in that binary, flush explicitly at each exit point and on SIGTERM, and pin the behaviour with a subprocess test that re-execs the binary, captures its output and asserts the final record survived.

`log.Fatalf` is a print followed by `os.Exit(1)`, and `os.Exit` terminates the process immediately without running deferred functions. The `defer w.Flush()` that was supposed to drain the `bufio.Writer` never runs, so up to a bufferful of the newest records — including the ones describing the failure — die with the process. The collector is not dropping anything; those bytes never reached a file descriptor. The fix I would make first is to remove the buffer and let the handler write straight to `os.Stdout`, so each record is out of the process the moment `Handle` returns. If buffering has to stay, ban `log.Fatal` in that binary, flush explicitly at each exit point and on SIGTERM, and pin the behaviour with a subprocess test that re-execs the binary, captures its output and asserts the final record survived.

code

go · 12 lines

func main() {
	w := bufio.NewWriter(os.Stdout)
	defer w.Flush() // never runs on the failure path
	logger := slog.New(slog.NewJSONHandler(w, nil))

	logger.Info("reconcile started")
	if err := reconcile(logger); err != nil {
		logger.Error("reconcile failed", "err", err) // still only in the buffer
		log.Fatalf("reconcile: %v", err)             // print, then os.Exit(1)
	}
	logger.Info("reconcile finished")
}

go deeper

for a junior

Remember that log.Fatal exits the process rather than returning, and that anything your program was holding in memory to write later is simply gone at that point.

for a middle

Explain the chain precisely: log.Fatal calls os.Exit, os.Exit runs no deferred functions, the deferred Flush is skipped, and the buffered records were never written to a descriptor.

for a senior

Diagnose it without blaming the platform, name every exit path that skips the flush, and prove the fix with a subprocess test rather than a manual run.

for a principal

Turn one incident into a fleet rule: unbuffered sinks by default, log.Fatal banned in service and job binaries, and a test in the shared template that fails if the tail stops surviving.

The chain, step by step

The job looks reasonable:

w := bufio.NewWriter(os.Stdout) — a 4096-byte buffer in front of the descriptor.
defer w.Flush() in main — the intended safety net.
a handler constructed over w, so every record goes into the buffer.
on failure, log.Fatalf("reconcile: %v", err).

Step 4 breaks steps 2 and 3. log.Fatalf writes its own message through the log package and then calls os.Exit(1). os.Exit is not a return: it asks the operating system to end the process on the spot. No deferred functions run, on any goroutine. The buffer is process memory, so whatever it held — quite possibly the whole run, if the job is quiet — is gone.

Notice which records you lose: the newest. The startup banner made it out because the buffer filled and drained naturally; the description of the failure did not. That is the worst possible failure mode for a log sink, because the tail is the part anyone reads.

Ruling out the innocent parties

On-call's first instinct is to blame the collector or the runtime, and that instinct wastes time. Two observations settle it:

The message that log.Fatalf itself printed does appear, because the log package writes to standard error unbuffered, not through your buffered handler. So you see the fatal line but not the structured records around it — a distinctive signature.
The lost records are contiguous and always at the end. A collector or runtime that was genuinely dropping data would drop under load, in the middle, not deterministically at the boundary.

Proving it, not guessing

The honest way to confirm the diagnosis and to keep it from coming back is a subprocess test. The child process runs the real failure path, including the real exit, and the parent inspects what actually crossed the descriptor:

func TestTailSurvivesFailure(t *testing.T) {
	if os.Getenv("BE_CHILD") == "1" {
		runReconcile() // the real path, ending the way production ends
		return
	}
	cmd := exec.Command(os.Args[0], "-test.run=^TestTailSurvivesFailure$")
	cmd.Env = append(os.Environ(), "BE_CHILD=1")
	out, err := cmd.CombinedOutput()
	if !strings.Contains(string(out), "reconcile failed") {
		t.Fatalf("tail lost: %q (%v)", out, err)
	}
}

This is the only kind of test that can see the problem at all: an in-process test never calls os.Exit, so it never exercises the path that loses the records. Once the test exists, someone re-adding a buffer for throughput gets a red build instead of a 3am surprise.

The fixes, in order of preference

Remove the buffer. Construct the handler over os.Stdout directly. Each record is one write call, the bytes are in the runtime's pipe before Handle returns, and no exit path can take them back. For a job that logs at human rates the syscall cost is invisible.

If the buffer must stay, stop exiting through log.Fatal. Have the failure path flush and then exit, and treat log.Fatal as banned in that binary — its whole design is to skip your cleanup. Add:

an explicit flush at every exit point, not just a defer;
a flush on every record at error level and above, so the interesting records never sit in memory;
a SIGTERM handler (signal.NotifyContext) that flushes on the way out, because a scheduled job that overruns its window is stopped by a signal, not by returning;
a periodic flush so a stuck job is not silent while somebody watches.

The paths that still beat you

Even with a diligent flush, a buffered sink stays fragile:

SIGKILL cannot be handled; anything buffered at that moment is lost.
Fatal runtime errors — a concurrent map write, the deadlock report, out of memory — run no deferred functions and no handlers.
A panic on another goroutine kills the program without unwinding main, so main's deferred flush never runs. (A panic on main's own goroutine does run it.)

Each of these is a reason the unbuffered sink is not merely simpler but categorically safer: there is no window in which a record exists only inside your process.

What this says about the design

A log sink's job is to get records out of the process as early as possible, because the process is the thing that is failing. Buffering optimises the case where everything is fine at the expense of the case you built logging for. That is why the default in a service or a job should be no buffer, and why buffering should require both a measurement and a proof that the tail survives.

## The chain, step by step The job looks reasonable: 1. `w := bufio.NewWriter(os.Stdout)` — a 4096-byte buffer in front of the descriptor. 2. `defer w.Flush()` in `main` — the intended safety net. 3. a handler constructed over `w`, so every record goes into the buffer. 4. on failure, `log.Fatalf("reconcile: %v", err)`. Step 4 breaks steps 2 and 3. `log.Fatalf` writes its own message through the `log` package and then calls `os.Exit(1)`. `os.Exit` is not a return: it asks the operating system to end the process on the spot. No deferred functions run, on any goroutine. The buffer is process memory, so whatever it held — quite possibly the whole run, if the job is quiet — is gone. Notice which records you lose: the newest. The startup banner made it out because the buffer filled and drained naturally; the description of the failure did not. That is the worst possible failure mode for a log sink, because the tail is the part anyone reads. ## Ruling out the innocent parties On-call's first instinct is to blame the collector or the runtime, and that instinct wastes time. Two observations settle it: - The message that `log.Fatalf` itself printed *does* appear, because the `log` package writes to standard error unbuffered, not through your buffered handler. So you see the fatal line but not the structured records around it — a distinctive signature. - The lost records are contiguous and always at the end. A collector or runtime that was genuinely dropping data would drop under load, in the middle, not deterministically at the boundary. ## Proving it, not guessing The honest way to confirm the diagnosis and to keep it from coming back is a subprocess test. The child process runs the real failure path, including the real exit, and the parent inspects what actually crossed the descriptor: ```go func TestTailSurvivesFailure(t *testing.T) { if os.Getenv("BE_CHILD") == "1" { runReconcile() // the real path, ending the way production ends return } cmd := exec.Command(os.Args[0], "-test.run=^TestTailSurvivesFailure$") cmd.Env = append(os.Environ(), "BE_CHILD=1") out, err := cmd.CombinedOutput() if !strings.Contains(string(out), "reconcile failed") { t.Fatalf("tail lost: %q (%v)", out, err) } } ``` This is the only kind of test that can see the problem at all: an in-process test never calls `os.Exit`, so it never exercises the path that loses the records. Once the test exists, someone re-adding a buffer for throughput gets a red build instead of a 3am surprise. ## The fixes, in order of preference **Remove the buffer.** Construct the handler over `os.Stdout` directly. Each record is one `write` call, the bytes are in the runtime's pipe before `Handle` returns, and no exit path can take them back. For a job that logs at human rates the syscall cost is invisible. **If the buffer must stay, stop exiting through `log.Fatal`.** Have the failure path flush and then exit, and treat `log.Fatal` as banned in that binary — its whole design is to skip your cleanup. Add: - an explicit flush at every exit point, not just a `defer`; - a flush on every record at error level and above, so the interesting records never sit in memory; - a SIGTERM handler (`signal.NotifyContext`) that flushes on the way out, because a scheduled job that overruns its window is stopped by a signal, not by returning; - a periodic flush so a stuck job is not silent while somebody watches. ## The paths that still beat you Even with a diligent flush, a buffered sink stays fragile: - **SIGKILL** cannot be handled; anything buffered at that moment is lost. - **Fatal runtime errors** — a concurrent map write, the deadlock report, out of memory — run no deferred functions and no handlers. - **A panic on another goroutine** kills the program without unwinding `main`, so `main`'s deferred flush never runs. (A panic on `main`'s own goroutine does run it.) Each of these is a reason the unbuffered sink is not merely simpler but categorically safer: there is no window in which a record exists only inside your process. ## What this says about the design A log sink's job is to get records out of the process as early as possible, because the process is the thing that is failing. Buffering optimises the case where everything is fine at the expense of the case you built logging for. That is why the default in a service or a job should be no buffer, and why buffering should require both a measurement and a proof that the tail survives.

Would the same records survive if the job died from an unrecovered panic instead?
If the panic is on the goroutine holding the defer, yes — unwinding runs deferred functions, so the flush happens before the runtime prints the trace and exits with status 2. But a panic on another goroutine ends the program without unwinding main, so main's deferred flush never runs, and fatal runtime errors such as a concurrent map write run no deferred functions at all.
Why can't an ordinary in-process test catch this?
Because the bug lives on the exit path. A normal test never calls os.Exit, so the deferred flush always runs and the assertion passes. You have to fork: re-exec the test binary with an environment guard, let the child take the real failure path, and assert on the bytes the parent captured from its stdout and stderr.
Besides log.Fatal, what else takes the tail of a buffered log sink?
Any os.Exit call, an uncaught SIGTERM when the scheduler stops an overrunning job, SIGKILL after the grace period, a fatal runtime error such as a concurrent map write, and a panic on a goroutine other than the one whose defer holds the flush. Each of them ends the process with the newest records still in memory.
The team says removing the buffer costs a syscall per record. How do you answer?
Ask for the measurement. Formatting and serialising a record usually costs more than the write that ships it, so if logging is hot the fix is fewer records — sampling or dropping per-request info — which saves more CPU and keeps the crash tail. Buffering optimises the healthy case at the expense of the failing one.

Buffering the log sink is like writing your incident notes on a whiteboard in the room that is on fire, and planning to photograph them on the way out. It works right up until you leave through the window.

saying these in an interview costs you the question

Says deferred functions always run before a process ends
Blames the collector or the container runtime for dropping lines
Adds a sleep before exiting so the buffer can drain
Assumes the operating system flushes user-space buffers at exit
Keeps log.Fatal and just makes the buffer smaller

A scheduled Go container job buffers its slog output and calls log.Fatal on failure. Why is the tail of its log missing?

§ answer

basics

solid answer

code

§ go deeper

▾level notes4 levels

▾deep dive~4 min

The chain, step by step

Ruling out the innocent parties

Proving it, not guessing

The fixes, in order of preference

The paths that still beat you

What this says about the design

▾common follow-ups4 questions

▾analogy~20 s

▾red flags5 flags

The chain, step by step

Ruling out the innocent parties

Proving it, not guessing

The fixes, in order of preference

The paths that still beat you

What this says about the design

answer

go deeper