Go ResponseHeaderTimeout — 1시간 타임아웃이 30초에 끊긴 이유

증상: 로그엔 여덟 글자뿐이었다

이 이야기는 타임아웃 조사로 시작하지 않았다. 운영에서 볼륨 attach가 간헐적으로 실패하는데, 로그에 남는 게 이게 전부였다.

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

http call failed. 어느 호스트로 간 어떤 요청이 왜 실패했는지 아무것도 없다. 원인은 에러를 읽는 쪽에 있었다. gRPC의 status details에는 실패 종류마다 다른 metadata가 실리는데, 상위 서비스는 그중 세 개의 키만 읽고 있었다.

특정 키를 고르는 대신 모든 ErrorInfo의 metadata를 병합하도록 고쳤다. 그러자 비로소 진짜 메시지가 드러났다.

{"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://...)"}

볼 곳은 cause 끝의 net/http: timeout awaiting response headers다. 이 커밋은 그 자체로는 아무 버그도 고치지 않았지만, 이게 없었으면 아래 조사는 시작조차 못 했다.

1시간을 걸었는데 30초에 끊겼다

호출 체인은 세 서비스, 세 저장소를 건넌다. 오케스트레이터가 클러스터 API를 부르고, 클러스터 API가 OpenStack 클라이언트를 부르고, 클라이언트가 Nova에 HTTP를 쏜다. 그리고 타임아웃은 분명히 걸려 있었다.

// 볼륨 생성/attach는 오래 걸릴 수 있으니 넉넉하게
const attachTimeout = 1 * time.Hour

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

1시간. 그런데 실패는 30초 언저리에 났다.

첫 가설: ctx가 어디선가 끊겼다

처음엔 어디선가 context.Background()로 갈아타서 deadline이 사라진 줄 알았다.

이게 첫 번째 오해였고, 이 오해가 시간을 꽤 잡아먹었다. 이 가설을 검증하려면 context가 프로세스 경계를 어떻게 넘는지부터 알아야 한다. context.Context는 Go 프로세스 안의 값이다. 네트워크를 건너지 않는다. 건너는 건 프로토콜이 따로 직렬화한 숫자 하나뿐이다.

전파 수단은 프로토콜마다 다르다. gRPC는 grpc-timeout 헤더로 자동 전파한다. 개발자가 할 일이 없다.

// 클라이언트: ctx에 deadline이 있으면 grpc-go가 알아서 grpc-timeout 헤더를 붙인다
resp, err := client.Invoke(ctx, req)

// 서버: 그 헤더를 읽어 handler ctx에 deadline을 심는다
func (s *Server) Invoke(ctx context.Context, in *Request) (*Response, error) {
  d, ok := ctx.Deadline() // ok == true, d ≈ 클라이언트가 건 시각
  // ...
}

go-micro는 timeout 헤더(나노초)로 보내고, 서버 플러그인이 읽어서 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()
}

마지막 홉인 HTTP는 http.NewRequestWithContext(ctx, ...)로 요청에 ctx를 붙인다. ctx가 죽으면 진행 중인 요청이 취소된다. 한 홉씩 전부 확인했다.

어디서도 context.Background()로 갈아타지 않았다. ctx 전파가 끊겼다는 가설은 틀렸다. 그래도 이 확인이 끝나야 그럼 ctx가 아닌 무언가가 끊었다로 넘어갈 수 있었다.

에러 문자열이 처음부터 범인을 가리키고 있었다

가설이 기각되고 나서야 에러 문자열을 다시 읽었다. 만약 ctx deadline이 만료됐다면 메시지는 달랐을 것이다.

context deadline exceeded                      ← ctx가 만료됐다면 이 문자열
net/http: timeout awaiting response headers    ← 실제로 남은 것

아래쪽은 Go 표준 라이브러리의 고정 문자열이고, http.Transport.ResponseHeaderTimeout이 만료됐을 때 나온다. 두 에러는 다른 사건이다.¹ 이걸 구분하는 순간 조사 방향이 완전히 바뀌었고, 범인은 바로 나왔다.

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

Go HTTP 요청에는 타이머가 몇 개인가

요청 한 건에는 호출자의 ctx deadline과 http.Client.Timeout이 전체에 걸리고, http.Transport에는 연결, TLS, 응답 헤더를 따로 재는 타이머가 있다. 이 타이머들은 서로를 모르고, 가장 먼저 만료되는 하나가 요청을 끊는다. 요청 한 건의 수명을 구간으로 쪼개면 어느 타이머가 어디를 덮는지 보인다.

표에서 볼 게 두 가지다. 첫째, ResponseHeaderTimeout은 서버가 일하는 시간, 곧 응답을 만드는 데 걸리는 시간을 잰다. 느린 API에 짧게 걸면 정상 응답을 잘라낸다. 둘째, 소유자가 다르다. ctx는 호출자가 갖고, Transport 타이머는 클라이언트 라이브러리를 만든 사람이 갖는다. 그 사람은 호출자가 무슨 정책을 세울지 모르고, 그 타이머는 대개 상수로 박혀 있어서 호출자가 볼 수도 바꿀 수도 없다.

왜 attach에서만 터졌나

Nova의 볼륨 attach는 POST /servers/{id}/os-volume_attachments다. 이 API는 응답을 보내기 전에 compute 노드에 동기 RPC를 걸어 디바이스 이름을 예약하고, Cinder 쪽 작업도 거친다. 실제로 하이퍼바이저에 디바이스를 붙이는 단계는 그 뒤에 이어진다. 인스턴스 락이나 compute 노드, Cinder 백엔드 상태에 따라 응답 헤더가 30초를 넘기는 일은 평소에도 있었다.

그러니 이 30초는 평범한 날에도 일정 비율로 걸리는 값이었다. 목록 조회처럼 빠른 API에서는 한 번도 안 걸렸기 때문에 아무도 몰랐을 뿐이다.

부수 피해: 성공한 attach가 실패로 남았다

여기까지가 타임아웃 버그다. 상수를 고치면 끝일 것 같았다. 그런데 운영 로그를 더 보니 훨씬 나쁜 게 있었다. Nova는 attach를 성공적으로 완료했다. 30초 안에 응답 헤더를 못 보냈을 뿐이다.

자가 회복이 불가능하다. 세 가지가 겹쳐서 생긴 구조다.

• attach는 비멱등(non-idempotent) 연산이다. 같은 볼륨을 두 번 붙일 수 없다. 두 번째 호출은 already in-use로 거부된다.
• 네트워크 에러는 연산이 일어나지 않았다는 뜻이 아니다. 요청은 도달했고 처리도 됐는데 응답만 유실될 수 있다. 클라이언트 입장에서 타임아웃과 서버가 요청을 못 받음은 구분이 안 된다.
• 재시도 판단이 자기 DB만 봤다. (action, state) 컬럼이 failed면 재시도. 실제 클러스터 상태를 다시 관측하는 코드가 어디에도 없었다.

이건 분산 시스템의 오래된 문제다. 응답이 안 오면 상대가 요청을 못 받았는지, 받고 처리했는데 응답이 죽었는지 알 수 없다. 대응은 셋 중 하나다. 연산을 멱등하게 만들거나(멱등 키), 실패 후 실제 상태를 다시 관측해서 판정을 정정하거나, 둘 다 하거나. 흥미롭게도 형제 모듈에는 이미 두 번째 해법이 있었다.

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 // 응답만 유실됐을 뿐 연산은 성공했다
  }
  return err
}

문제가 난 모듈에는 이게 없었을 뿐이다. 같은 코드베이스 안에 답이 있었는데 한쪽만 알고 있었다.

이 문제는 타임아웃을 늘려도 사라지지 않는다. 30초든 1시간이든 그 경계에 걸치는 요청은 생기고, 응답이 유실되는 창이 좁아질 뿐이다.

결함은 두 축이었다: 원인과 결과

여기서 문제의 모양이 바뀌었다. 결함은 서로 다른 저장소에 두 개 있었다.

어느 한쪽만 고치면 표의 오른쪽 칸이 남는다. 축 B는 즉시 배포했다. 응답 유실은 타임아웃 값과 무관하게 존재하므로 이 수정은 어느 쪽을 고르든 해야 한다. 문제는 축 A를 어디까지 고치느냐였다.

선택지 다섯 개를 하나씩 따져 봤다

할 수 있는 것은 많았다. 기준은 이 버그를 고치는 데 필요한 최소 수단이면서 결함의 클래스를 제거하는가였다.

① 메시지 큐로 비동기화: 기각

attach 같은 장시간 연산을 동기 RPC에서 걷어 내고 큐에 실으면 타임아웃 문제 자체가 사라진다. 재시도, 백오프, DLQ가 인프라 레벨로 올라가고, 부하 평탄화가 공짜로 따라온다. 매력적이다. 그런데 브로커라는 새 운영 대상이 생기고, API 계약이 동기에서 비동기로 바뀌어 호출자 전원이 상태 폴링을 새로 짜야 하고, 볼륨 생성 → attach → 복제 개시라는 순서 보장을 애플리케이션이 다시 구현해야 한다.

결정타는 따로 있었다. 큐는 대개 at-least-once다. 워커가 attach를 마치고 ack 직전에 죽으면 메시지가 재전달되고, 두 번째 attach는 already in-use로 실패한다. 비멱등 문제가 그대로 남는다. 큐를 써도 축 B의 재관측은 그대로 해야 한다는 뜻이고, 그게 이 안을 접은 이유였다.

② 앞단 재관측만: 필요하지만 충분하지 않다

저장소 하나, 배포 단위 하나. 검증된 패턴을 이식만 하면 되니 가장 빨리 운영에 반영된다. 실제로 먼저 배포했다. 하지만 30초 상한은 attach 전용이 아니다. 응답이 느린 모든 OpenStack API가 계속 잘린다. 인스턴스 생성, 스냅샷, 대량 목록 조회. 그리고 호출 지점마다 재관측 코드를 복제해야 한다. 이번 사건에서만 두 곳을 고쳤고, 세 번째는 시간 문제였다.

③ attach 경로만 별도 Transport: 기각

느린 API만 ResponseHeaderTimeout이 긴 별도 Transport를 쓰게 한다. 변경 표면이 극도로 작고 회귀 위험이 없다. 대신 어느 API가 느린지를 코드에 하드코딩하게 된다. 그건 환경마다 다르고 시간이 지나면 바뀐다. 그리고 ResponseHeaderTimeout은 Transport 필드라 Transport가 둘이 되면 커넥션 풀이 분리된다. 같은 호스트로 풀 두 개를 유지하게 되고 MaxConnsPerHost 계산이 이원화된다. attach 증상은 가려지지만 30초 상수는 그대로 남는다.

⑤ 모든 고정 타임아웃 정리: 분리

같은 원칙을 저장소 전체에 적용하면 일원화가 말 그대로 일원화가 된다. 하지만 폴링 상한 상수만 20개 가까이 되고 각각 다른 이유로 그 값이다. 토큰 갱신처럼 호출자 ctx를 그대로 쓸 수 없는 실제 제약도 있다. 캐시를 공유하는 구조에서 한 호출자의 취소가 다른 호출자의 토큰 갱신을 죽이면 안 된다. 리뷰가 불가능한 크기가 되고 릴리스 일정에 회귀 위험을 얹는다. 이번 범위에서 분리했다.

채택: 타임아웃의 소유자를 호출자 한 곳으로

ResponseHeaderTimeout을 제거해서 요청 상한을 호출자의 ctx deadline이 단독으로 소유하게 한다. attach뿐 아니라 느린 API 전부가 함께 낫고, 정책을 바꾸려면 호출자만 고치면 된다. 커넥션 풀도 하나로 유지된다.

var DefaultTransport = &http.Transport{
  DialContext: (&net.Dialer{
    Timeout:   3 * time.Second, // ✓ 남긴다: 연결 수립 방어는 ctx가 대체하지 못한다
    KeepAlive: 30 * time.Second,
  }).DialContext,
  TLSHandshakeTimeout: 5 * time.Second, // ✓ 남긴다: 같은 이유

  // ResponseHeaderTimeout 을 두지 않는다.
  // transport 상수는 ctx deadline 과 무관하게 요청을 끊어, 호출자가 건 타임아웃 정책을
  // 덮어쓴다. 요청 전체의 상한은 호출자의 ctx deadline 이 단독으로 소유한다.

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

Dialer.Timeout과 TLSHandshakeTimeout은 남겼다. 연결 수립은 서버가 일하는 시간이 아니다. 3초 안에 TCP가 안 열리면 그건 네트워크 문제이고, 짧게 걸어도 정상 동작을 해치지 않는다. 지울 것은 상위 정책을 덮어쓰는 상수뿐이었다. 그리고 삭제한 자리에 왜 없는지를 주석으로 남겼다. 필드가 없는 이유는 코드에서 읽히지 않으므로, 이게 없으면 누군가 선의로 다시 넣는다.

상한이 ctx로 옮겨 가면 에러 분류도 따라가야 한다

상수를 지우면 모든 타임아웃이 ctx를 거쳐서 일어난다. 이걸 이전처럼 전송 실패와 함께 Unavailable로 묶으면 서버가 죽었다와 우리가 기다리다 포기했다가 같은 코드로 보인다. 진단이 오히려 나빠진다.

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")
  }
}

errors.Is여야 한다. net/http는 ctx 에러를 *url.Error로 감싸서 돌려주는데, Unwrap()이 구현되어 있으므로 errors.Is는 그 껍질을 뚫고 도달한다.

// ✘ *url.Error{Err: context.DeadlineExceeded}와 비교하므로 항상 false
if err == context.DeadlineExceeded { /* ... */ }

// ✓ Unwrap 체인을 따라 내려가 원인을 찾는다
if errors.Is(err, context.DeadlineExceeded) { /* ... */ }

이 판별은 Do 호출과 body 읽기 구간 양쪽에 걸었다. 헤더 상한이 사라진 뒤로는 큰 목록 응답에서 deadline이 body를 읽는 중에 만료될 가능성이 크다. 거기서 io.ReadAll 에러를 Internal로 뭉뚱그리면 방금 한 분류가 정확히 그 자리에서 무너진다.

안전망은 deadline이 없는 호출에만 개입한다

상수를 없앴으니 deadline 없이 들어온 호출은 무한정 커넥션을 잡는다. 그래서 서버 쪽에 인터셉터를 하나 뒀다. 규칙은 하나다. 호출자가 준 deadline은 어떤 경우에도 덮어쓰지 않는다.

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) // ✓ 호출자 정책이 항상 우선
    }
    ctx, cancel := context.WithTimeout(ctx, timeout) // deadline이 없을 때만 기본값
    defer cancel()
    return handler(ctx, req)
  }
}

ctx.Deadline()의 두 번째 반환값 ok가 여기서 쓰인다. ok == false는 deadline이 아예 없다는 뜻이고, 이 인터셉터가 묻는 건 그것뿐이다. 체인 최외곽에 배치했다. 이후 모든 처리가 deadline 아래에서 돌아야 하니까.

// ChainUnaryInterceptor는 첫 번째 인자가 가장 바깥이다
// 반대로 알면 로깅이 deadline 바깥에서 돈다
grpc.ChainUnaryInterceptor(
  deadlineInterceptor(cfg.RequestTimeout),
  loggingInterceptor,
  authInterceptor,
)

대가: 커넥션 점유

ResponseHeaderTimeout이 있을 때는 응답 없는 엔드포인트에 물린 커넥션이 30초마다 스스로 풀렸다. 이제는 ctx deadline까지 묶인다. MaxConnsPerHost가 128이므로 대량 동시 실패 때 풀이 고갈될 여지가 있다.

처음엔 인터셉터가 상한을 보장하니 위험이 낮다고 생각했다.

이건 틀렸다. 인터셉터는 deadline이 없는 호출에만 개입한다. deadline이 있는 호출은 설계상 건드리지 않으므로, 호출자 deadline이 있으면 그 값이 그대로 상한이고 기본값은 그걸 줄여 주지 않는다. 그리고 이 사건의 주인공인 attach는 1시간을 건다. 비정상적으로 긴 deadline이라며 배제했던 시나리오가 바로 기본 시나리오였다.

그래서 이 트레이드오프는 알고서 받아들였다. 운영 중 커넥션 고갈이 관측되면 호출자 deadline을 줄인다. 서버 기본값은 deadline 없는 호출에만 적용되니, 낮춰도 attach 같은 호출에는 닿지 않는다.

초록불인데 아무것도 지키지 못하는 테스트

ResponseHeaderTimeout 제거를 행위로 검증하려면 30초 넘게 지연되는 서버가 필요하다. CI에서 40초짜리 테스트는 현실적이지 않다. 그래서 회귀 방지의 주력은 구조적 단정으로 뒀다.

// 호출자가 건 deadline이 유일한 상한이어야 하므로 0(무제한)이어야 한다.
// 누가 상수를 다시 넣는 회귀는 이 한 줄이 잡는다.
func TestDefaultTransportHasNoResponseHeaderTimeout(t *testing.T) {
  if got := httpclient.DefaultTransport.ResponseHeaderTimeout; got != 0 {
    t.Fatalf("ResponseHeaderTimeout = %v, want 0", got)
  }
}

인터셉터 쪽에서 더 재미있는 걸 배웠다. 인터셉터 단위 테스트 네 개가 전부 통과했는데, 서버 체인 등록에서 인터셉터를 빼도 전부 통과했다. 테스트가 deadlineInterceptor(...)를 직접 호출하고 있었기 때문이다. 기능의 가치 전부가 ChainUnaryInterceptor 한 줄에 달려 있는데, 정확히 그 한 줄만 무방비였다.

// ✘ 인터셉터를 직접 호출: main.go 배선이 빠져도 초록불
_, err := deadlineInterceptor(3*time.Minute)(ctx, req, info, handler)

// ✓ main과 같은 체인으로 서버를 띄우고(기본 deadline만 짧게), deadline 없는 ctx로 요청한다
// 핸들러는 ctx가 끝날 때까지 기다린다. 배선이 빠지면 영원히 기다리다 테스트 타임아웃으로 빨간불
client := newTestClient(t, 50*time.Millisecond)
_, err = client.Call(context.Background(), req)
require.Equal(t, codes.DeadlineExceeded, status.Code(err)) // gRPC 에러는 status 코드로 본다

이 테스트는 체인에서 인터셉터를 빼고 돌려 빨간불이 켜지는 걸 확인한 뒤에 넣었다.

정리

고친 것은 두 축에 걸쳐 있다.

이 사건에서 가장 오래 걸린 건 ctx를 걸었으니 그게 상한이라는 전제를 의심하는 일이었다. 그리고 타임아웃을 고치고 나서야 진짜 문제가 보였다. 비멱등 연산 앞에서 응답이 안 왔다는 건 결과를 모른다는 뜻이고, 모르면 다시 봐야 한다.

다음에 타임아웃이 예상보다 일찍 나면 이 순서로 본다.

1. 에러 문자열. context deadline exceeded인지 net/http: timeout awaiting response headers인지에 따라 끊은 타이머가 다르다.
2. 호출 경로에 있는 http.Client와 http.Transport의 타이머 필드. 하위 라이브러리가 쓰는 기본 Transport까지 연다.
3. 비멱등 연산이면 실패 처리 경로. 타임아웃 뒤에 실제 상태를 다시 보는지 확인한다.

함께 읽으면 좋은 글: Go context 완전 정리에서 deadline이 트리를 따라 줄어드는 원리를, 호출 300번을 1번으로에서 최적화가 실패 모드를 바꾸는 이야기를 다뤘다.

참고 자료

• net/http · Transport: ResponseHeaderTimeout, TLSHandshakeTimeout, IdleConnTimeout이 각각 재는 구간
• net/http · Client: body 읽기까지 포함하는 Client.Timeout
• net/url · Error.Unwrap: errors.Is가 *url.Error를 뚫고 원인에 닿는 이유
• gRPC · Deadlines: grpc-timeout 헤더로 deadline이 전파되는 방식
• grpc-go · ChainUnaryInterceptor: 첫 번째 인터셉터가 가장 바깥이라는 순서 규칙
• Nova API · Attach a volume to an instance: POST /servers/{server_id}/os-volume_attachments