HAProxy HTTP 로그: 타이머와 종료 상태

HTTP 로그 형식

frontend 에 option httplog 를 쓰면 HTTP 형식이 켜집니다. 매뉴얼은 이것을 다음 log-format 문자열과 정확히 같다고 정의합니다.

# strict equivalent of "option httplog"
log-format "%ci:%cp [%tr] %ft %b/%s %TR/%Tw/%Tc/%Tr/%Ta %ST %B %CC \
            %CS %tsc %ac/%fc/%bc/%sc/%rc %sq/%bq %hr %hs %{+Q}r"

syslog 를 거쳐 파일에 남은 한 줄입니다.

Oct 18 10:02:02 lb1 haproxy[2201]: 198.51.100.7:40110 [18/Oct/2026:10:01:57.020] fe_http be_api/api-3 0/0/0/120/5032 200 65536 - - SD-- 315/301/44/15/0 0/0 "GET /api/export HTTP/1.1"

예시 읽기: 서버는 120 ms 만에 헤더를 보냈고(Tr), 본문이 흐르는 도중 서버 쪽 연결이 오류로 끊겼습니다(SD). 클라이언트는 요청 도착 5032 ms 뒤에 200 과 함께 더 컸어야 할 응답 중 64 KiB 만 받았습니다. 상태 코드는 성공이라 말하고, 종료 상태는 다운로드가 깨졌다고 말합니다.

awk 위치가 밀릴 때

위 위치는 전통 syslog 머리(Mmm dd hh:mm:ss host)를 가정합니다. RFC 5424 나 ISO-8601 머리는 앞에 오는 낱말 수가 다르고, 호스트 이름이 하나 더 붙어 전달된 로그도 마찬가지입니다. 캡처한 헤더는 큐 칸 뒤의 칸만 밉니다. 헷갈리면 타이머 칸(빗금으로 나뉜 숫자 다섯 개)을 찾아 거기서부터 세십시오. 아래의 타이머 칸을 찾는 명령이 바로 그렇게 합니다. 보드는 머리 모양과 상관없이 클라이언트 주소와 요청 시각을 찾아 거기서부터 읽습니다.

다섯 타이머: TR / Tw / Tc / Tr / Ta

값은 모두 밀리초입니다. 요청 하나가 프록시를 지나는 길을 따라갑니다.

요청 첫 바이트                                          응답 마지막 바이트
|                                                                         |
|-- TR --|-- Tw --|-- Tc --|-------- Tr --------|---------- Td ----------|
 요청      큐        TCP      서버가 응답 헤더를      응답 본문이
 헤더      대기      연결     보낼 때까지 일함        클라이언트로 나감
|<------------------------------- Ta ------------------------------------>|

TR 앞: Th(TCP 수락 + TLS · PROXY 핸드셰이크), Ti(유휴, keep-alive)
Tq = Th + Ti + TR      Tt = Th + Ti + Ta      Td = Ta - (TR + Tw + Tc + Tr)

원인을 가리키는 타이머 모양

Th · Ti · Td · Tt · Tq · Tu

• Th: TCP 수락과 TLS · PROXY 프로토콜 핸드셰이크입니다. 연결의 첫 요청에만 찍히고 뒤 요청은 0 입니다.
• Ti: 요청 전 유휴 시간입니다. 미리 맺어 둔 연결이나 keep-alive 연결이 기다린 시간이며, 아무것도 받지 못했으면 -1 입니다.
• Td: 헤더 뒤 응답 본문 전송 시간입니다. 기본 형식에는 없으므로 Ta − (TR + Tw + Tc + Tr) 로 구하고, -1 인 타이머는 빼고 계산합니다.
• Tt: 수락부터 닫힐 때까지 연결 전체 시간입니다. HTTP 에서는 Tt = Th + Ti + Ta 입니다.
• Tq: Th + Ti + TR 입니다. 예전 HAProxy 는 같은 자리에 Tq/Tw/Tc/Tr/Tt 를 남겼습니다. Tq 와 Tt 는 핸드셰이크와 유휴 시간을 품으므로 keep-alive 연결에서 훨씬 커 보이며, 매뉴얼은 Tq 대신 TR 을 권합니다.
• Tu: 사용자가 느끼는 시간 추정치입니다. 연결 전체 시간에서 유휴 시간 Ti 를 뺀 값입니다.

종료 상태: 네 글자

11번 칸은 TCP 로그에서 두 글자, HTTP 로그에서 네 글자입니다. 앞 두 글자는 연결이 어떻게 끝났는지, 뒤 두 글자는 지속 쿠키 이야기이며 쿠키를 쓰지 않으면 -- 입니다. 그래서 「SD--」를 검색했다면 중요한 것은 SD 이고, cD-- 는 쿠키와 상관없는 cD 입니다.

첫 글자: 무엇이 끝냈나

둘째 글자: 어느 단계였나

셋째 · 넷째 글자: 지속 쿠키

종료 상태 참고표: 흔한 조합

매뉴얼이 꼽은 조합, 쉬운 말 풀이, 다음에 볼 곳입니다. 대문자는 중단 · 오류, 소문자는 시간 초과입니다.

쿠키 조합

「자꾸 다시 로그인해야 한다」는 민원이 있으면 그 시각의 II · DI · VI · EI · OI 를 보십시오. 하나하나가 원래 서버를 떠난 요청입니다.

연결 수 · 재시도 · 큐

HAProxy 로그에서 보드가 보여 주는 것

• 종료 상태 — 상태별 건수와 쉬운 말 풀이, 비정상인 것부터.
• 요청 해부 — TR · Tw · Tc · Tr · 전송 시간을 쌓은 막대. 시간이 큐에 갔는지, 연결에 갔는지, 서버에 갔는지 보입니다.
• 로그로 그린 구성도 — 4 · 5번 칸으로 frontend → backend → server 를 그립니다. 굵기는 트래픽, 빨강은 오류가 나는 곳입니다.
• 재시도와 큐 대기 — backend · 서버별.
• 먼저 볼 것 — 예: 「HAProxy SD 61회 — backend be_api, 서버 api-3」.
• 그 밖의 기본 카드 — 상태 코드, 상위 경로, 상위 클라이언트, 지연, 시간축.

HAProxy 로그용 한 줄 명령

전통 syslog 머리를 단 option httplog 표본으로 실행해 확인했습니다. 머리가 다르면 모든 칸 번호에 같은 차이를 더하거나 빼고, 아니면 타이머 칸을 찾는 명령을 쓰십시오.

• 모든 종료 상태, 많은 순

  awk '{print $15}' haproxy.log | sort | uniq -c | sort -rn

  복사

• 앞 두 글자만(쿠키 글자 무시)

  awk '{print substr($15, 1, 2)}' haproxy.log | sort | uniq -c | sort -rn

  복사

• 위치를 믿지 않고 같은 일 — 타이머 칸을 찾아 다섯 칸 뒤를 읽습니다

  awk '{for (i = 1; i <= NF; i++) if ($i ~ /^-?[0-9]+\/-?[0-9]+\/-?[0-9]+\/-?[0-9]+\/\+?[0-9]+$/) {print $(i+5); next}}' haproxy.log | sort | uniq -c | sort -rn

  복사

• backend/server 별 비정상 종료

  awk 'substr($15, 1, 1) != "-" {print substr($15, 1, 2), $9}' haproxy.log | sort | uniq -c | sort -rn

  복사

• backend 별 상태 코드

  awk '{split($9, b, "/"); print b[1], $11}' haproxy.log | sort | uniq -c | sort -rn

  복사

• 서버가 헤더를 보내는 데 1초 넘게 걸린 요청(Tr)과 종료 상태

  awk '{split($10, t, "/"); if (t[4] > 1000) print t[4], $9, $15}' haproxy.log | sort -rn

  복사

• 큐에서 기다린 요청(Tw > 0)과 큐 위치

  awk '{split($10, t, "/"); if (t[2] > 0) print t[2], $9, $17}' haproxy.log | sort -rn

  복사

• 서버와 연결이 끝내 맺어지지 않은 요청(Tc = -1)

  awk '{split($10, t, "/"); if (t[3] == -1 && t[2] != -1) print $9, $11, $15}' haproxy.log | sort | uniq -c

  복사

• 재시도가 있는 요청. "+" 는 재분배

  awk '{split($16, c, "/"); if (c[5] != "0") print c[5], $9, $15}' haproxy.log

  복사

• 서버에 닿지 못한 요청 수

  grep -c '/<NOSRV> ' haproxy.log

  복사

• 전체 활성 시간 Ta 의 p99

  awk '{split($10, t, "/"); sub(/^\+/, "", t[5]); print t[5]}' haproxy.log | sort -n | awk '{a[NR]=$1} END {i=int(NR*0.99); if (i<NR*0.99) i++; print a[i] " ms"}'

  복사

• 본 것 중 가장 큰 프로세스 전체 연결 수

  awk '{split($16, c, "/"); if (c[1] > m) m = c[1]} END {print "peak actconn", m}' haproxy.log

  복사

• 본문 전송 시간이 가장 긴 요청(Td = Ta − TR − Tw − Tc − Tr)

  awk '{split($10, t, "/"); if (t[1] >= 0 && t[2] >= 0 && t[3] >= 0 && t[4] >= 0) print t[5]-(t[1]+t[2]+t[3]+t[4]), $9}' haproxy.log | sort -rn | head -3

  복사