TT Lab
Get started
Learn Learning paths Courses

Observability

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

Continue in TT Lab

Goal

With one fixed log file, you build a cost table by level, implement per-request sampling, error retention, repeat collapsing, and a per-second cap yourself to turn the trade-off between cost and investigability into numbers, and then pin it down in a policy file.

Why it matters

The demand to cut log costs always comes. The easiest answers then are 'raise the level' and 'sample', but if both are done wrong, only cost goes down and investigation ability goes to 0. That is because the unit a person reads when investigating is not a line but the bundle of lines a request left behind. If you keep 10% per line, no request can be read to the end, but if you keep 10% per request, that 10% is complete. If you add one more rule, 'requests that ended in an error are not dropped', the retention rate of failed requests goes from 0% to 100% with cost nearly unchanged. The table you build in this lab is evidence you can use as is at the next cost meeting.

Steps

  1. The source log is /opt/lab/logsample/app.log. The line format is <시각> <수준> req=<id> handler=<경로> msg="<메시지>" (timestamp, level, request id, handler path, message), and the levels are the four DEBUG, INFO, WARN, and ERROR. In /root/obs-log-sampling/cost.tsv, write four lines with no header, and each line has three tab-separated columns, <수준> <줄 수> <바이트> (level, line count, bytes). Bytes is the number of bytes the lines of that level occupy and includes one newline character per line.
  2. Write the result of dropping all DEBUG lines as six lines in /root/obs-log-sampling/drop-debug.txt. They are kept_lines=<남은 줄 수>, kept_bytes=<남은 바이트>, saved_pct=<바이트 기준 절감률, 소수 두 자리>, req=<오류로 끝난 요청 중 request_id 가 사전순으로 가장 앞선 것>, req_lines_before=<그 요청의 원래 줄 수>, and req_lines_after=<DEBUG 를 뺀 뒤 그 요청에 남은 줄 수>. The values are, in order: the remaining line count, the remaining bytes, the byte-based savings rate to two decimal places, the alphabetically first request_id among requests that ended in an error, that request's original line count, and its line count after removing DEBUG. A 'request that ended in an error' is a request with at least one line whose level is ERROR.
  3. Create /root/obs-log-sampling/sample.py. When called as python3 sample.py --rate N < 입력 > 출력 (with the input file and the output file), it reads the lines on standard input and writes only the lines to keep, unchanged, to standard output (keeping the input order). The criterion for keeping is per request — letting r be the req= value of a line, keep the line if int(hashlib.md5(r.encode()).hexdigest()[:8], 16) % N == 0. --rate 1 keeps everything. Then create the result file with python3 sample.py --rate 10 < /opt/lab/logsample/app.log > /root/obs-log-sampling/sampled-10.log.
  4. Add a --keep-errors option to /root/obs-log-sampling/sample.py. With this option, a request that has even one line whose level is ERROR keeps all its lines regardless of the sampling rate (keeping the input order). Without the option, the behavior must be the same as in step 3. Then create the result with python3 sample.py --rate 10 --keep-errors < /opt/lab/logsample/app.log > /root/obs-log-sampling/sampled-10-err.log.
  5. Changing the sampling rate N to 1, 4, 10, and 50, create /root/obs-log-sampling/tradeoff.tsv. It has four lines with no header, and each line has five tab-separated columns, <N> <표본만 썼을 때 남은 줄 수> <그때 완전히 남은 오류 요청 수> <오류 보존까지 켰을 때 남은 줄 수> <그때 완전히 남은 오류 요청 수> (N, the line count with sampling only, the number of error requests fully retained then, the line count with error retention on, and the number of error requests retained then). 'Error requests fully retained' counts the requests, among those that ended in an error, that have at least one line remaining in the result file.
  6. Create /root/obs-log-sampling/squeeze.py. When called as python3 squeeze.py [--max-debug-per-sec K] < 입력 > 출력 (with the input and output files; K defaults to 20), it applies two rules in order. ① If a line has the same (level, handler, msg) as the line immediately before it, treat them as one run and keep only the first line, but if the run's line count k is 2 or more, append repeated=<k> to the end of that line. ② After collapsing, for DEBUG lines only, keep up to K lines from the start within the same second (the first 19 characters of the timestamp string) and discard the rest. Then create python3 squeeze.py < /opt/lab/logsample/app.log > /root/obs-log-sampling/squeezed.log, and write four lines in_lines=, after_collapse=, after_cap=, and bytes_saved_pct=<소수 두 자리> (two decimal places) in /root/obs-log-sampling/squeeze.txt.
  7. Feed the output of sample.py --rate 10 --keep-errors straight into squeeze.py (default cap) to create /root/obs-log-sampling/final.log. Then write eight lines in /root/obs-log-sampling/final.txt — in_lines=, out_lines=, in_bytes=, out_bytes=, reduction_pct=<바이트 기준, 소수 두 자리> (byte-based, two decimal places), error_requests_kept=<final.log 에 줄이 남아 있는 오류 요청 수> (the number of error requests that have lines remaining in final.log), trace_req=<2단계에서 고른 그 요청 id> (the request id chosen in step 2), and trace_lines=<final.log 에 남은 그 요청의 줄 수> (the number of that request's lines remaining in final.log).
  8. Write /root/obs-log-sampling/policy.yml as YAML. Under levels, put retain_days (an integer) and sample_rate (an integer) for each of the four levels DEBUG, INFO, WARN, and ERROR. ERROR's sample_rate must be 1 and its retain_days must be greater than DEBUG's. DEBUG's sample_rate must be 2 or more. Under rules, put keep_errors_whole_request: true, collapse_repeats: true, and max_debug_per_sec (the default value used in step 6). Under estimate, write raw_bytes, kept_bytes, and reduction_pct with the same values as the step 7 result, and at the end write the trade-off of this policy as a single sentence of at least 40 characters in note.

Notes

First count how much each level is costing

The source log is /opt/lab/logsample/app.log. The line format is <시각> <수준> req=<id> handler=<경로> msg="<메시지>" (timestamp, level, request id, handler path, message), and the levels are the four DEBUG, INFO, WARN, and ERROR. In /root/obs-log-sampling/cost.tsv, write four lines with no header, and each line has three tab-separated columns, <수준> <줄 수> <바이트> (level, line count, bytes). Bytes is the number of bytes the lines of that level occupy and includes one newline character per line.

The level is the second whitespace-separated field. You can extract it with awk '{print $2}'. For bytes, accumulate the line length plus 1, as in awk '{n[$2]++; b[$2]+=length($0)+1}'. The proportions of the four numbers are the starting point of this lab — see which level takes up most of the volume.

What remains and what disappears when you turn off DEBUG

Write the result of dropping all DEBUG lines as six lines in /root/obs-log-sampling/drop-debug.txt. They are kept_lines=<남은 줄 수>, kept_bytes=<남은 바이트>, saved_pct=<바이트 기준 절감률, 소수 두 자리>, req=<오류로 끝난 요청 중 request_id 가 사전순으로 가장 앞선 것>, req_lines_before=<그 요청의 원래 줄 수>, and req_lines_after=<DEBUG 를 뺀 뒤 그 요청에 남은 줄 수>. The values are, in order: the remaining line count, the remaining bytes, the byte-based savings rate to two decimal places, the alphabetically first request_id among requests that ended in an error, that request's original line count, and its line count after removing DEBUG. A 'request that ended in an error' is a request with at least one line whose level is ERROR.

You can find the alphabetically first ID with grep ' ERROR ' | grep -o 'req=[0-9a-f]*' | sort -u | head -1. To see only that request's lines, use grep 'req=<id>' (the placeholder is the request id). The question of this step is not the number of remaining lines but whether you can read that request's flow.

Sample requests, not lines

Create /root/obs-log-sampling/sample.py. When called as python3 sample.py --rate N < 입력 > 출력 (with the input file and the output file), it reads the lines on standard input and writes only the lines to keep, unchanged, to standard output (keeping the input order). The criterion for keeping is per request — letting r be the req= value of a line, keep the line if int(hashlib.md5(r.encode()).hexdigest()[:8], 16) % N == 0. --rate 1 keeps everything. Then create the result file with python3 sample.py --rate 10 < /opt/lab/logsample/app.log > /root/obs-log-sampling/sampled-10.log.

Because the decision is applied to the request and not the line, a request's lines are either kept whole or lost whole. That is all there is to this filter — if you pick any request_id in the result file and grep it, the line count equals the original. You must use the hashing method exactly as written in the task. The grader recomputes with the same rule and compares line by line.

Do not drop requests that ended in an error from the sample

Add a --keep-errors option to /root/obs-log-sampling/sample.py. With this option, a request that has even one line whose level is ERROR keeps all its lines regardless of the sampling rate (keeping the input order). Without the option, the behavior must be the same as in step 3. Then create the result with python3 sample.py --rate 10 --keep-errors < /opt/lab/logsample/app.log > /root/obs-log-sampling/sampled-10-err.log.

You can only know which requests ended in an error by reading the file to the end, so you have to scan twice — first collect the request_ids of the ERROR lines, then scan the lines again and decide. Compare with the step 3 result to see how much the number of lines grows when you add this rule. It grows less than you would expect.

Make a table of the trade-off between sampling rate and investigability

Changing the sampling rate N to 1, 4, 10, and 50, create /root/obs-log-sampling/tradeoff.tsv. It has four lines with no header, and each line has five tab-separated columns, <N> <표본만 썼을 때 남은 줄 수> <그때 완전히 남은 오류 요청 수> <오류 보존까지 켰을 때 남은 줄 수> <그때 완전히 남은 오류 요청 수> (N, the line count with sampling only, the number of error requests fully retained then, the line count with error retention on, and the number of error requests retained then). 'Error requests fully retained' counts the requests, among those that ended in an error, that have at least one line remaining in the result file.

You just run sample.py eight times, changing only the options. You can count the error requests with grep ' ERROR ' <결과> | grep -o 'req=[0-9a-f]*' | sort -u | wc -l (the placeholder is the result file). See where the third column becomes 0, and by how much the fourth column grows compared with the second then.

Collapse repeats and apply a per-second cap

Create /root/obs-log-sampling/squeeze.py. When called as python3 squeeze.py [--max-debug-per-sec K] < 입력 > 출력 (with the input and output files; K defaults to 20), it applies two rules in order. ① If a line has the same (level, handler, msg) as the line immediately before it, treat them as one run and keep only the first line, but if the run's line count k is 2 or more, append repeated=<k> to the end of that line. ② After collapsing, for DEBUG lines only, keep up to K lines from the start within the same second (the first 19 characters of the timestamp string) and discard the rest. Then create python3 squeeze.py < /opt/lab/logsample/app.log > /root/obs-log-sampling/squeezed.log, and write four lines in_lines=, after_collapse=, after_cap=, and bytes_saved_pct=<소수 두 자리> (two decimal places) in /root/obs-log-sampling/squeeze.txt.

Collapse only when lines are 'consecutive' — if a line of another request comes in between, it is a different run. For after_collapse, it is easy to run it once more with a very large cap and count. The reason the cap is applied only to DEBUG is the heart of this step. If you apply it regardless of level, ERROR gets cut off at the very moment of a runaway, and only the logs of the time they are most needed disappear.

Application 1 — chain the two filters and confirm that investigation still works

Feed the output of sample.py --rate 10 --keep-errors straight into squeeze.py (default cap) to create /root/obs-log-sampling/final.log. Then write eight lines in /root/obs-log-sampling/final.txt — in_lines=, out_lines=, in_bytes=, out_bytes=, reduction_pct=<바이트 기준, 소수 두 자리> (byte-based, two decimal places), error_requests_kept=<final.log 에 줄이 남아 있는 오류 요청 수> (the number of error requests that have lines remaining in final.log), trace_req=<2단계에서 고른 그 요청 id> (the request id chosen in step 2), and trace_lines=<final.log 에 남은 그 요청의 줄 수> (the number of that request's lines remaining in final.log).

Both filters use standard input and output, so you can connect them with a pipe. Compare trace_lines with req_lines_before from step 2 — how it differs from when you turned off DEBUG is the conclusion of this lab. If it is a request whose repeats were collapsed, the line count may be smaller than the original.

Application 2 — pin down levels, sampling rates, retention periods, and cost in a policy file

Write /root/obs-log-sampling/policy.yml as YAML. Under levels, put retain_days (an integer) and sample_rate (an integer) for each of the four levels DEBUG, INFO, WARN, and ERROR. ERROR's sample_rate must be 1 and its retain_days must be greater than DEBUG's. DEBUG's sample_rate must be 2 or more. Under rules, put keep_errors_whole_request: true, collapse_repeats: true, and max_debug_per_sec (the default value used in step 6). Under estimate, write raw_bytes, kept_bytes, and reduction_pct with the same values as the step 7 result, and at the end write the trade-off of this policy as a single sentence of at least 40 characters in note.

Check the syntax first with python3 -c "import yaml,sys;yaml.safe_load(open('policy.yml'))". Do not copy the numbers by hand; read them from final.txt and fill them in, and you will make no mistakes. When deciding retention periods, ask 'will we ever need to look for this level several days later?' — what you look for in a quarterly retrospective is ERROR, not DEBUG.