Go ResponseHeaderTimeout — why a one-hour timeout died at 30 seconds

Symptom: the logs said three words

This didn’t start as a timeout investigation. Volume attaches were failing intermittently in production, and this was all the logs had to say.

Cause: ipc failed bad request
  {"cause":"rpc error: code = Unavailable desc = http call failed"}

http call failed. Nothing about which host, which request, or why. The problem was on the side reading the error. gRPC status details carry different metadata for different kinds of failure, and the upstream service read only three of those keys.

Instead of picking specific keys, I changed it to merge the metadata from every ErrorInfo. Only then did the real message appear.

{"cause":"rpc error: code = Unavailable desc = http call failed
  (cause=Post \"https://<nova-host>:18774/v2.1/servers/.../os-volume_attachments\":
   net/http: timeout awaiting response headers, method=POST, url=https://...)"}

The part to look at is the end of cause: net/http: timeout awaiting response headers. That commit fixed no bug by itself, but without it the investigation below couldn’t even have started.

One hour set, cut at 30 seconds

The call chain crosses three services and three repositories. The orchestrator calls the cluster API, the cluster API calls the OpenStack client, and the client sends HTTP to Nova. And the timeout was clearly set.

// Creating and attaching volumes can take a while, so be generous
const attachTimeout = 1 * time.Hour

_, err := cluster.AttachVolume(ctx, req, client.WithRequestTimeout(attachTimeout))

One hour. Yet the failures came at around 30 seconds.

First hypothesis: the ctx got dropped somewhere

At first I assumed something along the way switched to context.Background() and the deadline was lost.

That was the first misconception, and it cost a fair amount of time. To test it, you first need to know how context crosses a process boundary. A context.Context is a value inside a Go process; it doesn’t travel over the network. What travels is a single number that the protocol serializes separately.

How it travels depends on the protocol. gRPC propagates it automatically in the grpc-timeout header; there’s nothing for the developer to do.

// Client: if ctx has a deadline, grpc-go adds the grpc-timeout header for you
resp, err := client.Invoke(ctx, req)

// Server: that header is read and the deadline is planted in the handler's ctx
func (s *Server) Invoke(ctx context.Context, in *Request) (*Response, error) {
  d, ok := ctx.Deadline() // ok == true, d ≈ the time the client set
  // ...
}

go-micro sends a timeout header (in nanoseconds), and the server plugin reads it and applies WithTimeout.

// go-micro grpc client plugin
header["timeout"] = fmt.Sprintf("%d", opts.RequestTimeout)

// go-micro grpc server plugin
if n, err := strconv.ParseUint(to, 10, 64); err == nil {
  ctx, cancel = context.WithTimeout(ctx, time.Duration(n))
  defer cancel()
}

The last hop, HTTP, attaches the ctx to the request with http.NewRequestWithContext(ctx, ...). If the ctx dies, the in-flight request is canceled. I checked every hop.

Nothing switched to context.Background(). The idea that ctx propagation broke was wrong. Still, only after that check could I move on to “then something other than ctx cut it off.”

The error string had pointed at the culprit all along

Only after rejecting the hypothesis did I reread the error string. If the ctx deadline had expired, the message would have been different.

context deadline exceeded                      ← what an expired ctx produces
net/http: timeout awaiting response headers    ← what we actually got

The second is a fixed string in Go’s standard library, produced when http.Transport.ResponseHeaderTimeout expires. They are two different events.¹ The moment I told them apart, the investigation turned around and the culprit showed up immediately.

var DefaultTransport = &http.Transport{
  DialContext: (&net.Dialer{
    Timeout:   3 * time.Second,
    KeepAlive: 30 * time.Second,
  }).DialContext,
  TLSHandshakeTimeout:   5 * time.Second,
  ResponseHeaderTimeout: 30 * time.Second, // ← this
  IdleConnTimeout:       90 * time.Second,
  MaxConnsPerHost:       128,
}

How many timers does a Go HTTP request have?

The caller’s ctx deadline and http.Client.Timeout cover the whole request, and http.Transport has separate timers for connecting, the TLS handshake, and waiting for response headers. These timers don’t know about each other, and whichever expires first cuts the request off. Split one request’s lifetime into phases and you can see which timer covers what.

Two things stand out. First, ResponseHeaderTimeout measures the time the server spends working, that is, how long it takes to build a response. Set it short on a slow API and it cuts off healthy responses. Second, the owners differ. The caller owns the ctx; whoever wrote the client library owns the Transport timers. That person has no idea what policy the caller will set, and those timers are usually hard-coded where callers can neither see nor change them.

Why only attach blew up

Nova’s volume attach is POST /servers/{id}/os-volume_attachments. Before responding, this API makes a synchronous RPC to the compute node to reserve a device name and goes through work on the Cinder side; physically attaching the device to the hypervisor comes afterward. Depending on instance locks and the state of the compute node and Cinder backend, response headers took more than 30 seconds on ordinary days, too.

So these 30 seconds fired a certain fraction of the time on an ordinary day. Nobody noticed because fast APIs like listing never hit it.

Collateral damage: a successful attach recorded as failed

That’s the timeout bug. Fixing the constant seemed like the end of it. But digging further into production logs turned up something much worse. Nova had completed the attach successfully. It just hadn’t sent response headers within 30 seconds.

It can’t recover on its own. Three things combine to cause it.

• Attach is non-idempotent. You can’t attach the same volume twice; the second call is rejected with already in-use.
• A network error doesn’t mean the operation didn’t happen. The request can arrive and be processed while only the response is lost. From the client’s side, a timeout and “the server never got the request” are indistinguishable.
• The retry decision looked only at its own database. If the (action, state) columns said failed, it retried. Nothing anywhere re-observed the actual cluster state.

This is an old distributed-systems problem. When no response comes back, you can’t tell whether the other side never got the request or processed it and the response died. There are three responses: make the operation idempotent (idempotency keys), re-observe the actual state after a failure and correct the verdict, or both. Interestingly, a sibling module already had the second one.

if err := attach(ctx, vol); err != nil {
  attached, lerr := listAttachedVolumes(ctx, instanceID)
  if lerr == nil && contains(attached, vol.ID) {
    logger.Warn("treat attach as success: volume is already attached")
    return nil // only the response was lost; the operation succeeded
  }
  return err
}

The module that broke simply didn’t have this. The answer was already in the same codebase; only one side knew it.

Raising the timeout doesn’t make this go away. At 30 seconds or an hour, some request will straddle the boundary; the window where responses get lost only narrows.

Two defects: cause and consequence

Here the problem changed shape. There were two defects, in two different repositories.

Fix only one and the right-hand column of the table is what’s left. Axis B shipped immediately, since lost responses exist regardless of the timeout value and the fix is needed whichever option wins. The question was how far to take axis A.

Weighing five options one by one

There was plenty I could do. The criteria were the smallest change that fixes this bug, and whether it removes the whole class of defect.

① Go async with a message queue: rejected

Move long operations like attach off synchronous RPC and onto a queue, and the timeout problem disappears entirely. Retries, backoff, and a DLQ move into infrastructure, and load leveling comes for free. Tempting. But it adds a broker to operate, changes the API contract from sync to async so every caller has to write new status polling, and forces the application to re-implement ordering guarantees like create volume → attach → start replication.

The decisive blow was elsewhere. Queues are usually at-least-once. If a worker finishes the attach and dies just before acking, the message is redelivered and the second attach fails with already in-use. The non-idempotency problem remains. Even with a queue, axis B’s re-observation would still have to be done, and that’s why I dropped this option.

② Re-observe up front only: necessary but not sufficient

One repository, one deploy unit. Porting a proven pattern gets it into production fastest, and in fact it shipped first. But the 30-second cap isn’t specific to attach. Every slow OpenStack API keeps getting cut off: instance creation, snapshots, large listings. And every call site would need its own copy of the re-observation code. This incident alone needed two; a third was only a matter of time.

③ A separate Transport just for attach: rejected

Give only the slow APIs a separate Transport with a longer ResponseHeaderTimeout. The change surface is tiny and there’s no regression risk. But it hard-codes “which APIs are slow,” which varies by environment and changes over time. And since ResponseHeaderTimeout is a Transport field, two Transports mean two connection pools, two pools to the same host, and MaxConnsPerHost math split in two. The attach symptom gets covered up, and the 30-second constant stays where it is.

⑤ Clean up every fixed timeout: split off

Applying the same principle across the whole repository would make “one owner” literally true. But there are nearly 20 polling-limit constants alone, each with its own reason. Some have real constraints that prevent using the caller’s ctx directly, like token refresh: with a shared cache, one caller canceling must not kill another caller’s token refresh. It would grow past reviewable size and put regression risk on the release schedule. I split it out of this change.

The choice: one owner for the timeout, the caller

Remove ResponseHeaderTimeout so that the caller’s ctx deadline alone owns the request limit. Attach and every other slow API get better together; changing the policy means changing only the caller; and there’s still one connection pool.

var DefaultTransport = &http.Transport{
  DialContext: (&net.Dialer{
    Timeout:   3 * time.Second, // ✓ keep: ctx can't stand in for guarding connection setup
    KeepAlive: 30 * time.Second,
  }).DialContext,
  TLSHandshakeTimeout: 5 * time.Second, // ✓ keep: same reason

  // No ResponseHeaderTimeout.
  // A transport constant cuts requests regardless of the ctx deadline, overriding
  // the caller's timeout policy. The caller's ctx deadline alone owns the request limit.

  IdleConnTimeout: 90 * time.Second,
  MaxConnsPerHost: 128,
}

Dialer.Timeout and TLSHandshakeTimeout stayed. Connection setup isn’t time the server spends working. If TCP doesn’t open in 3 seconds, that’s a network problem, and a short limit doesn’t hurt normal operation. The only constant to remove was the one overriding upper-layer policy. I also left a comment explaining why the field is gone. A missing field’s reason can’t be read from code, and without the comment someone will helpfully add it back.

When the limit moves to ctx, error classification has to follow

With the constant gone, every timeout now happens through ctx. Lump those in with transport failures as Unavailable like before, and “the server died” looks the same as “we gave up waiting.” Diagnosis would get worse.

func mapRequestError(err error, method, rawURL string) error {
  switch {
  case errors.Is(err, context.DeadlineExceeded):
    return status.Error(codes.DeadlineExceeded, "http call timeout")
  case errors.Is(err, context.Canceled):
    return status.Error(codes.Canceled, "http call canceled")
  default:
    return status.Error(codes.Unavailable, "http call failed")
  }
}

It has to be errors.Is. net/http wraps ctx errors in a *url.Error, which implements Unwrap(), so errors.Is reaches through the wrapper.

// ✘ compares against *url.Error{Err: context.DeadlineExceeded}, so always false
if err == context.DeadlineExceeded { /* ... */ }

// ✓ follows the Unwrap chain down to the cause
if errors.Is(err, context.DeadlineExceeded) { /* ... */ }

This check sits around both the Do call and reading the body. With the header limit gone, the deadline on a large listing response is likely to expire while the body is being read. Lump io.ReadAll errors into Internal there, and the classification you just built falls apart in exactly that spot.

The safety net only steps in when there’s no deadline

With the constant gone, calls that arrive without a deadline hold connections indefinitely. So I added an interceptor on the server side, with one rule: never override a deadline the caller provided.

func deadlineInterceptor(timeout time.Duration) grpc.UnaryServerInterceptor {
  return func(ctx context.Context, req any, _ *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (any, error) {
    if timeout <= 0 {
      return handler(ctx, req)
    }
    if _, ok := ctx.Deadline(); ok {
      return handler(ctx, req) // ✓ the caller's policy always wins
    }
    ctx, cancel := context.WithTimeout(ctx, timeout) // default only when there's no deadline
    defer cancel()
    return handler(ctx, req)
  }
}

This is where the second return value of ctx.Deadline(), ok, earns its keep. ok == false means there’s no deadline at all, and that’s the only thing this interceptor asks. It sits outermost in the chain, because everything after it needs to run under a deadline.

// In ChainUnaryInterceptor, the first argument is the outermost
// Get it backwards and logging runs outside the deadline
grpc.ChainUnaryInterceptor(
  deadlineInterceptor(cfg.RequestTimeout),
  loggingInterceptor,
  authInterceptor,
)

The cost: holding connections longer

With ResponseHeaderTimeout, a connection stuck on an unresponsive endpoint freed itself every 30 seconds. Now it’s held until the ctx deadline. With MaxConnsPerHost at 128, a burst of simultaneous failures could exhaust the pool.

At first I thought the interceptor guaranteed a limit, so the risk was low.

That was wrong. The interceptor only steps in for calls with no deadline. By design it leaves calls with a deadline alone, so when the caller sets one, that value is the limit as-is, and the default doesn’t shorten it. And the protagonist of this story, attach, sets one hour. The scenario I had dismissed as an unusually long deadline was the default scenario.

So I accepted the trade-off knowingly. If connection exhaustion shows up in production, we shorten the caller’s deadline. The server default only applies to calls without a deadline, so lowering it wouldn’t reach calls like attach.

A green test that protects nothing

Verifying the removal of ResponseHeaderTimeout behaviorally needs a server that stalls for more than 30 seconds, and a 40-second test in CI isn’t realistic. So the main regression guard is a structural assertion.

// The caller's deadline must be the only limit, so this must be 0 (no limit).
// This one line catches anyone putting the constant back.
func TestDefaultTransportHasNoResponseHeaderTimeout(t *testing.T) {
  if got := httpclient.DefaultTransport.ResponseHeaderTimeout; got != 0 {
    t.Fatalf("ResponseHeaderTimeout = %v, want 0", got)
  }
}

The interceptor side taught me something more interesting. All four interceptor unit tests passed, and they still passed after I removed the interceptor from the server chain, because the tests called deadlineInterceptor(...) directly. The feature’s entire value hung on one ChainUnaryInterceptor line, and that was exactly the line left unprotected.

// ✘ Calls the interceptor directly: green even if the main.go wiring is missing
_, err := deadlineInterceptor(3*time.Minute)(ctx, req, info, handler)

// ✓ Start a server with the same chain as main (only a shorter default deadline) and call with no deadline
// The handler waits until ctx ends. Without the wiring it waits forever and the test times out red
client := newTestClient(t, 50*time.Millisecond)
_, err = client.Call(context.Background(), req)
require.Equal(t, codes.DeadlineExceeded, status.Code(err)) // check gRPC errors by status code

I removed the interceptor from the chain, ran this test, saw it go red, and only then committed it.

Wrapping up

The fixes span both axes.

What took longest in this incident was doubting the premise that setting a ctx meant setting the limit. And only after fixing the timeout did the real problem show itself. In front of a non-idempotent operation, “no response came back” means the outcome is unknown, and when you don’t know, you go and look again.

The next time a timeout fires earlier than expected, this is the order I’ll check things in:

1. The error string. context deadline exceeded and net/http: timeout awaiting response headers come from different timers.
2. The timer fields on every http.Client and http.Transport along the call path, including the default Transport inside lower-level libraries.
3. For non-idempotent operations, the failure path. Check whether it re-observes the real state after a timeout.

Related reading: Go context, fully explained covers how deadlines shrink down the tree, and From 300 calls to 1 is about how optimization changes failure modes.

References

• net/http · Transport: the phases measured by ResponseHeaderTimeout, TLSHandshakeTimeout, and IdleConnTimeout
• net/http · Client: Client.Timeout, which includes reading the body
• net/url · Error.Unwrap: why errors.Is reaches through a *url.Error
• gRPC · Deadlines: how deadlines propagate in the grpc-timeout header
• grpc-go · ChainUnaryInterceptor: the first interceptor is the outermost
• Nova API · Attach a volume to an instance: POST /servers/{server_id}/os-volume_attachments