skip to content

A Go audit-log service logs 947 accepted and 812 drained records at exit; where did the other 135 go?

level: seniorimportance: nice to knowfreq 26%

answer

  1. distrust the counters before the code
  2. count started work, not pending work
  3. a batch holds about a hundred items
  4. flush after the wait, before the release
  5. the drain budget lives inside the kill budget

basics

~20 s

Three seams swallow them: records admitted after the refusal flag was set, records sitting in an in-memory batch the WaitGroup never counted, and records marked done before their flush completed. Instrument each seam, then report the shortfall.

solid answer

~50 s

Treat the gap as an accounting bug first. Records disappear at three seams: admitted through the window between the closing check and the count, so they were never waited for; sitting in an in-memory batch or channel buffer that the `WaitGroup` never counted, because it counts *started* work; or counted as done by a worker whose `defer wg.Done()` ran before the write was actually flushed to durable storage. Instrument each seam separately — accepted, started, flushed, dropped — and increment them at exactly the boundaries they name. Then fix the shape: make admission atomic, flush the buffer after `Wait` returns and before the output is released, and size the drain budget strictly inside the termination grace period the platform allows before it sends a hard kill, leaving room to flush and to write the shutdown line. Return a non-nil error when the drain expires, so nothing reports a clean exit.

code

go · 15 lines
go
func (w *Writer) Shutdown(ctx context.Context) error {
	start := time.Now()
	w.stopAccepting() // accepted stops moving here

	err := w.drain(ctx) // bounded wait on the per-record group

	// the batch was never counted by the WaitGroup: flush it before release
	flushed, dropped := w.flushBatch()
	w.out.Close()

	log.Printf("drain: accepted=%d flushed=%d dropped=%d took=%s err=%v",
		w.accepted.Load(), w.flushed.Load()+flushed, dropped,
		time.Since(start), err)
	return err
}

go deeper

for a junior

Know that a counter reaching zero only covers work that was counted, and that anything still queued or buffered has to be flushed separately before the process exits.

for a middle

Name the seams and where each counter should be incremented: at admission, at pickup, after the flush completes, and at each deliberate drop. Explain why a buffered batch is invisible to the group.

for a senior

Work the incident end to end: instrument first, get the flush-then-release ordering right, fix the admission window, bound the wait, and make an incomplete drain produce an error and a log line rather than a silent clean exit.

for a principal

Own the shared number. The drain budget and the platform's termination allowance are two halves of one setting owned by different people, and you should be able to say who changes what, how a mismatch is detected before an incident, and when durable-on-admission is worth its cost.

## Read the two numbers first 947 accepted, 812 drained. Before touching the code, decide what those counters actually count, because the most common outcome of this investigation is that no records were lost at all and the two counters were incremented at different boundaries. If `accepted` is bumped when the caller hands over a record and `drained` is bumped by the worker that writes it, they are only comparable if every accepted record must be written by a worker before exit — which is precisely the property under investigation. Circular counters like these are worse than none. So the first fix is instrumentation: four counters, each incremented at exactly the seam it names. - **accepted** — immediately after the admission decision succeeds, in the same critical section as the count. - **started** — when a worker picks the record up. - **flushed** — after the write has actually reached durable storage, not merely after the write call returned into a buffer. - **dropped** — wherever a record is deliberately abandoned, with a label for which seam abandoned it. With those, `accepted - flushed - dropped` should be zero at exit, and if it is not you know which seam swallowed the difference. ## The three seams **Seam one: admitted after the drain began.** If the accept path reads the closing flag and then counts the record as two separate steps, a record can be admitted after `Wait` has already returned at a zero counter. It runs against a service that has declared itself drained and dies with the process. The tell is that the loss is small, non-deterministic, and clusters at shutdown. **Seam two: never counted at all.** A `WaitGroup` counts work that has been started and counted — nothing else. Records queued in a channel's buffer waiting for a worker, or accumulated in an in-memory batch waiting for a size or time trigger to flush them, are invisible to it. The counter reaches zero, the drain declares success, and the batch evaporates. This is the seam that produces *large*, systematic losses, and it is by far the likeliest explanation for 135 records at once, because a batch is exactly the shape that holds a hundred-odd items. The fix is ordering: after `Wait` returns, flush the batch, and only then release the output. If the batch itself is drained by a goroutine, that goroutine has to be part of a wait too — but a separate one, waited on after the per-record group, because it is what consumes their output. **Seam three: done before durable.** `defer wg.Done()` at the top of a worker fires when the function returns, which is not the same instant as the bytes reaching disk or the remote endpoint. If the worker writes into a `bufio.Writer` or an application-level batch and returns, the record is counted as drained while it is still only in memory. The counter is then measuring "handed off", not "written", and the flush ordering above is what closes it. ## The budget, and who owns it Even a perfectly instrumented drain loses everything if the process is killed halfway through it. The service runs under a termination allowance: something asks it to stop, then hard-kills it after a fixed period. The drain budget must fit strictly inside that period, with room reserved for the post-`Wait` flush and for writing the shutdown summary — if the drain deadline equals the grace period, the kill lands while the flush is running and the counters never even print, which is why the incident report has no evidence in it. That makes the budget a shared parameter rather than a code detail. The platform engineer who sets the termination allowance and the service owner who sets the drain deadline are configuring two halves of one number, and neither can be changed unilaterally. Practical shape: read the drain budget from configuration, default it conservatively below the platform's allowance, log both values at startup so a mismatch is visible before an incident, and log the actual drain duration at exit so you can see how close to the ceiling real shutdowns run. ## Making the report honest The last defect in the original service is that it exited quietly. A drain that did not finish must return a non-nil error from the shutdown path, and that error should reach the process's exit status and a single structured log line carrying the four counters and the elapsed drain time. Then "did we lose audit records during yesterday's rollout" is a query, not an archaeology project. If the workload allows it, the strongest version is to make the loss impossible instead of merely visible: persist accepted records to local durable storage at admission and treat the in-memory path as a cache. That is a bigger change and it moves the failure to a different place rather than removing it, but for an audit trail it is often the right trade. ## What the interviewer is testing Whether you reach for accounting before theories, whether you know that a `WaitGroup` covers only started-and-counted work, whether you get the flush-after-wait-before-release ordering right, and whether you connect the drain deadline to the external kill deadline instead of picking a round number.

  • Why is a batch of buffered records the most likely explanation for a loss of exactly 135?
    A WaitGroup counts started work, so anything queued in a channel buffer or accumulated in an in-memory batch is invisible to it. That produces one large, systematic loss at the moment of exit rather than the small, jittery losses an admission race gives. The size matching a plausible batch is the strongest clue.
  • How should the drain deadline relate to the platform's termination grace period?
    Strictly shorter, with headroom for the post-wait flush and for writing the shutdown summary. If they are equal, the hard kill lands during the flush and no counters are ever emitted, which is why incidents like this often leave no evidence. Log both values at startup so a mismatch is caught before it matters.
  • Where exactly should defer wg.Done() run if writes go through a buffered writer?
    The counter then measures handoff, not durability, so Done marking the worker complete is fine only if the drain flushes that buffer after the wait and before closing the output. Otherwise move the accounting: count a record as drained when its bytes are flushed, not when the worker function returns.
  • What is the strongest fix if losing an audit record is unacceptable?
    Persist at admission to local durable storage and treat the in-memory path as a cache that a separate process or a restart can replay. It costs latency and moves the failure rather than deleting it, but it removes the dependency on finishing a drain inside a grace period that something else controls.

saying these in an interview costs you the question

  • Blaming the missing records on goroutine scheduling
  • Assuming a zero WaitGroup counter means nothing is pending
  • Closing the output before flushing the batch
  • Setting the drain deadline equal to the kill deadline
  • Exiting with status zero after an incomplete drain