LabHub
배우기 러닝패스 코스

Observability

The day we turned on debug logs, the lines we needed disappeared

LabHub 에서 이어서 보기

한국어 원문으로 표시합니다.

목표

고정된 로그 파일 하나로 수준별 비용 표를 만들고, 요청 단위 표본·오류 보존·반복 접기·초당 상한을 직접 구현해 비용과 조사 가능성의 맞바꿈을 숫자로 만든 뒤 정책 파일로 못박습니다.

왜 중요한가

로그 비용을 줄이라는 요구는 항상 온다. 그때 가장 쉬운 답이 '수준을 올린다' 와 '표본을 뽑는다' 인데, 둘 다 잘못하면 비용만 줄고 조사 능력은 0 이 된다. 사람이 조사할 때 읽는 단위는 줄이 아니라 한 요청이 남긴 줄의 묶음이기 때문이다. 줄 단위로 10% 를 남기면 어느 요청도 끝까지 읽을 수 없지만, 요청 단위로 10% 를 남기면 그 10% 는 완전하다. 여기에 '오류로 끝난 요청은 빼지 않는다' 는 규칙 하나를 더하면 비용은 거의 그대로인 채 실패한 요청의 보존율이 0% 에서 100% 로 올라간다. 이 실습에서 만드는 표는 다음번 비용 회의에서 그대로 쓸 수 있는 근거다.

단계

  1. 재료 로그는 /opt/lab/logsample/app.log 입니다. 줄 형식은 <시각> <수준> req=<id> handler=<경로> msg="<메시지>" 이고 수준은 DEBUG·INFO·WARN·ERROR 넷입니다. /root/obs-log-sampling/cost.tsv 에 머리글 없이 네 줄, 각 줄은 탭으로 나눈 세 칸 <수준> <줄 수> <바이트> 를 적으세요. 바이트는 그 수준의 줄들이 차지하는 바이트 수이고 줄바꿈 문자 한 개를 포함합니다.
  2. DEBUG 줄을 전부 버렸을 때의 결과를 /root/obs-log-sampling/drop-debug.txt 에 여섯 줄로 적으세요. kept_lines=<남은 줄 수>, kept_bytes=<남은 바이트>, saved_pct=<바이트 기준 절감률, 소수 두 자리>, req=<오류로 끝난 요청 중 request_id 가 사전순으로 가장 앞선 것>, req_lines_before=<그 요청의 원래 줄 수>, req_lines_after=<DEBUG 를 뺀 뒤 그 요청에 남은 줄 수> 입니다. '오류로 끝난 요청' 은 수준이 ERROR 인 줄을 하나 이상 가진 요청입니다.
  3. /root/obs-log-sampling/sample.py 를 만드세요. python3 sample.py --rate N < 입력 > 출력 으로 부르면 표준 입력의 줄을 읽어 남길 줄만 그대로 표준 출력에 씁니다(입력 순서 유지). 남기는 기준은 요청 단위입니다 — 줄의 req= 값을 r 이라 할 때 int(hashlib.md5(r.encode()).hexdigest()[:8], 16) % N == 0 이면 그 줄을 남깁니다. --rate 1 은 전부 남깁니다. 그다음 python3 sample.py --rate 10 < /opt/lab/logsample/app.log > /root/obs-log-sampling/sampled-10.log 로 결과 파일을 만드세요.
  4. /root/obs-log-sampling/sample.py 에 --keep-errors 옵션을 더하세요. 이 옵션이 있으면 수준이 ERROR 인 줄을 하나라도 가진 요청은 표본률과 무관하게 모든 줄을 남깁니다(입력 순서 유지). 옵션이 없을 때의 동작은 3단계와 같아야 합니다. 그다음 python3 sample.py --rate 10 --keep-errors < /opt/lab/logsample/app.log > /root/obs-log-sampling/sampled-10-err.log 로 결과를 만드세요.
  5. 표본률 N 을 1·4·10·50 으로 바꿔 가며 /root/obs-log-sampling/tradeoff.tsv 를 만드세요. 머리글 없이 네 줄이고 각 줄은 탭으로 나눈 다섯 칸 <N> <표본만 썼을 때 남은 줄 수> <그때 완전히 남은 오류 요청 수> <오류 보존까지 켰을 때 남은 줄 수> <그때 완전히 남은 오류 요청 수> 입니다. '완전히 남은 오류 요청' 은 오류로 끝난 요청 중 결과 파일에 줄이 하나라도 남아 있는 요청을 셉니다.
  6. /root/obs-log-sampling/squeeze.py 를 만드세요. python3 squeeze.py [--max-debug-per-sec K] < 입력 > 출력 (K 기본값 20)으로 부르면 두 규칙을 차례로 적용합니다. ① 바로 앞 줄과 (수준, handler, msg) 가 모두 같으면 한 덩어리로 보고 첫 줄만 남기되, 덩어리의 줄 수 k 가 2 이상이면 그 줄 끝에 repeated=<k> 를 붙입니다. ② 접은 뒤, DEBUG 줄만 같은 초(시각 문자열의 앞 19자) 안에서 앞에서부터 K 개까지 남기고 나머지는 버립니다. 그다음 python3 squeeze.py < /opt/lab/logsample/app.log > /root/obs-log-sampling/squeezed.log 를 만들고, /root/obs-log-sampling/squeeze.txt 에 네 줄 in_lines=, after_collapse=, after_cap=, bytes_saved_pct=<소수 두 자리> 를 적으세요.
  7. sample.py --rate 10 --keep-errors 의 출력을 squeeze.py(기본 상한)에 그대로 흘려 /root/obs-log-sampling/final.log 를 만드세요. 그리고 /root/obs-log-sampling/final.txt 에 여덟 줄을 적으세요 — in_lines=, out_lines=, in_bytes=, out_bytes=, reduction_pct=<바이트 기준, 소수 두 자리>, error_requests_kept=<final.log 에 줄이 남아 있는 오류 요청 수>, trace_req=<2단계에서 고른 그 요청 id>, trace_lines=<final.log 에 남은 그 요청의 줄 수> 입니다.
  8. /root/obs-log-sampling/policy.yml 을 YAML 로 쓰세요. levels 아래 DEBUG·INFO·WARN·ERROR 네 수준마다 retain_days(정수)와 sample_rate(정수) 를 둡니다. ERROR 의 sample_rate 는 1 이어야 하고 retain_days 는 DEBUG 보다 커야 합니다. DEBUG 의 sample_rate 는 2 이상이어야 합니다. rules 아래에는 keep_errors_whole_request: true, collapse_repeats: true, max_debug_per_sec(6단계에서 쓴 기본값)를 둡니다. estimate 아래에는 raw_bytes·kept_bytes·reduction_pct 를 7단계 결과와 같은 값으로 적고, 마지막에 note 로 이 정책의 맞바꿈을 40자 이상 한 문장으로 적으세요.

참고

수준별로 얼마를 쓰고 있는지부터 센다

재료 로그는 /opt/lab/logsample/app.log 입니다. 줄 형식은 <시각> <수준> req=<id> handler=<경로> msg="<메시지>" 이고 수준은 DEBUG·INFO·WARN·ERROR 넷입니다. /root/obs-log-sampling/cost.tsv 에 머리글 없이 네 줄, 각 줄은 탭으로 나눈 세 칸 <수준> <줄 수> <바이트> 를 적으세요. 바이트는 그 수준의 줄들이 차지하는 바이트 수이고 줄바꿈 문자 한 개를 포함합니다.

수준은 공백으로 나눈 둘째 칸입니다. awk '{print $2}' 로 꺼낼 수 있습니다. 바이트는 awk '{n[$2]++; b[$2]+=length($0)+1}' 처럼 줄 길이에 1 을 더해 모으면 됩니다. 네 숫자의 비율이 이 실습의 출발점입니다 — 어느 수준이 부피의 대부분을 차지하는지 보세요.

DEBUG 를 끄면 무엇이 남고 무엇이 사라지나

DEBUG 줄을 전부 버렸을 때의 결과를 /root/obs-log-sampling/drop-debug.txt 에 여섯 줄로 적으세요. kept_lines=<남은 줄 수>, kept_bytes=<남은 바이트>, saved_pct=<바이트 기준 절감률, 소수 두 자리>, req=<오류로 끝난 요청 중 request_id 가 사전순으로 가장 앞선 것>, req_lines_before=<그 요청의 원래 줄 수>, req_lines_after=<DEBUG 를 뺀 뒤 그 요청에 남은 줄 수> 입니다. '오류로 끝난 요청' 은 수준이 ERROR 인 줄을 하나 이상 가진 요청입니다.

사전순으로 가장 앞선 아이디는 grep ' ERROR ' | grep -o 'req=[0-9a-f]*' | sort -u | head -1 로 찾을 수 있습니다. 그 요청의 줄만 보려면 grep 'req=<id>' 하면 됩니다. 남은 줄 수가 아니라 그 요청의 흐름을 읽을 수 있는가 가 이 단계의 질문입니다.

줄이 아니라 요청을 표본으로 뽑는다

/root/obs-log-sampling/sample.py 를 만드세요. python3 sample.py --rate N < 입력 > 출력 으로 부르면 표준 입력의 줄을 읽어 남길 줄만 그대로 표준 출력에 씁니다(입력 순서 유지). 남기는 기준은 요청 단위입니다 — 줄의 req= 값을 r 이라 할 때 int(hashlib.md5(r.encode()).hexdigest()[:8], 16) % N == 0 이면 그 줄을 남깁니다. --rate 1 은 전부 남깁니다. 그다음 python3 sample.py --rate 10 < /opt/lab/logsample/app.log > /root/obs-log-sampling/sampled-10.log 로 결과 파일을 만드세요.

판정을 줄이 아니라 요청에 걸기 때문에 한 요청의 줄이 통째로 남거나 통째로 사라집니다. 그것이 이 필터의 전부입니다 — 결과 파일에서 아무 request_id 나 골라 grep 해 보면 원본과 줄 수가 같습니다. 해시 방식은 과제에 적힌 그대로 써야 합니다. 채점기가 같은 규칙으로 다시 계산해 줄 단위로 맞춰 봅니다.

오류로 끝난 요청은 표본에서 빼지 않는다

/root/obs-log-sampling/sample.py 에 --keep-errors 옵션을 더하세요. 이 옵션이 있으면 수준이 ERROR 인 줄을 하나라도 가진 요청은 표본률과 무관하게 모든 줄을 남깁니다(입력 순서 유지). 옵션이 없을 때의 동작은 3단계와 같아야 합니다. 그다음 python3 sample.py --rate 10 --keep-errors < /opt/lab/logsample/app.log > /root/obs-log-sampling/sampled-10-err.log 로 결과를 만드세요.

어떤 요청이 오류로 끝났는지는 파일을 끝까지 읽어야 알 수 있으므로 두 번 훑어야 합니다 — 먼저 ERROR 줄의 request_id 를 모으고, 그다음 줄을 다시 훑으며 판정합니다. 이 규칙을 넣으면 줄 수가 얼마나 늘어나는지 3단계 결과와 비교해 보세요. 생각보다 적게 늡니다.

표본률과 조사 가능성의 맞바꿈을 표로 만든다

표본률 N 을 1·4·10·50 으로 바꿔 가며 /root/obs-log-sampling/tradeoff.tsv 를 만드세요. 머리글 없이 네 줄이고 각 줄은 탭으로 나눈 다섯 칸 <N> <표본만 썼을 때 남은 줄 수> <그때 완전히 남은 오류 요청 수> <오류 보존까지 켰을 때 남은 줄 수> <그때 완전히 남은 오류 요청 수> 입니다. '완전히 남은 오류 요청' 은 오류로 끝난 요청 중 결과 파일에 줄이 하나라도 남아 있는 요청을 셉니다.

sample.py 를 옵션만 바꿔 여덟 번 돌리면 됩니다. 오류 요청 수는 grep ' ERROR ' <결과> | grep -o 'req=[0-9a-f]*' | sort -u | wc -l 로 셀 수 있습니다. 셋째 칸이 어디서 0 이 되는지, 그리고 그때 넷째 칸이 둘째 칸보다 얼마나 늘어나는지를 보세요.

반복을 접고 초당 상한을 건다

/root/obs-log-sampling/squeeze.py 를 만드세요. python3 squeeze.py [--max-debug-per-sec K] < 입력 > 출력 (K 기본값 20)으로 부르면 두 규칙을 차례로 적용합니다. ① 바로 앞 줄과 (수준, handler, msg) 가 모두 같으면 한 덩어리로 보고 첫 줄만 남기되, 덩어리의 줄 수 k 가 2 이상이면 그 줄 끝에 repeated=<k> 를 붙입니다. ② 접은 뒤, DEBUG 줄만 같은 초(시각 문자열의 앞 19자) 안에서 앞에서부터 K 개까지 남기고 나머지는 버립니다. 그다음 python3 squeeze.py < /opt/lab/logsample/app.log > /root/obs-log-sampling/squeezed.log 를 만들고, /root/obs-log-sampling/squeeze.txt 에 네 줄 in_lines=, after_collapse=, after_cap=, bytes_saved_pct=<소수 두 자리> 를 적으세요.

접기는 '연속' 일 때만 합니다 — 사이에 다른 요청의 줄이 끼면 다른 덩어리입니다. after_collapse 는 상한을 아주 크게 준 채로 한 번 더 돌려 세면 쉽습니다. 상한을 DEBUG 에만 거는 이유가 이 단계의 핵심입니다. 수준을 가리지 않고 걸면 폭주하는 그 순간에 ERROR 가 잘려 나가, 가장 필요한 시각의 로그만 사라집니다.

응용 ① — 두 필터를 이어 붙이고 조사가 되는지 확인한다

sample.py --rate 10 --keep-errors 의 출력을 squeeze.py(기본 상한)에 그대로 흘려 /root/obs-log-sampling/final.log 를 만드세요. 그리고 /root/obs-log-sampling/final.txt 에 여덟 줄을 적으세요 — in_lines=, out_lines=, in_bytes=, out_bytes=, reduction_pct=<바이트 기준, 소수 두 자리>, error_requests_kept=<final.log 에 줄이 남아 있는 오류 요청 수>, trace_req=<2단계에서 고른 그 요청 id>, trace_lines=<final.log 에 남은 그 요청의 줄 수> 입니다.

두 필터 모두 표준 입출력을 쓰므로 파이프로 이으면 됩니다. trace_lines 를 2단계의 req_lines_before 와 비교해 보세요 — DEBUG 를 껐을 때와 무엇이 다른지가 이 실습의 결론입니다. 반복이 접힌 요청이라면 줄 수가 원래보다 줄어들 수도 있습니다.

응용 ② — 수준·표본률·보존기간·비용을 정책 파일로 못박는다

/root/obs-log-sampling/policy.yml 을 YAML 로 쓰세요. levels 아래 DEBUG·INFO·WARN·ERROR 네 수준마다 retain_days(정수)와 sample_rate(정수) 를 둡니다. ERROR 의 sample_rate 는 1 이어야 하고 retain_days 는 DEBUG 보다 커야 합니다. DEBUG 의 sample_rate 는 2 이상이어야 합니다. rules 아래에는 keep_errors_whole_request: true, collapse_repeats: true, max_debug_per_sec(6단계에서 쓴 기본값)를 둡니다. estimate 아래에는 raw_bytes·kept_bytes·reduction_pct 를 7단계 결과와 같은 값으로 적고, 마지막에 note 로 이 정책의 맞바꿈을 40자 이상 한 문장으로 적으세요.

python3 -c "import yaml,sys;yaml.safe_load(open('policy.yml'))" 로 문법을 먼저 확인하세요. 숫자는 손으로 옮기지 말고 final.txt 에서 읽어 채우면 실수가 없습니다. 보존 기간을 정할 때는 '이 수준을 며칠 뒤에 찾을 일이 있는가' 를 물어보세요 — 분기 회고에서 찾는 것은 ERROR 이지 DEBUG 가 아닙니다.