Narrowing the Cause From Logs

Goal

You pull evidence from production logs (catalina.out, GC log, access log, nginx error log), narrow down the cause of an outage, and become able to write an incident report with numbers in it.

Why it matters

The most common failure in incident response is lengthening the timeout for a 502. A 502 means "an invalid response was received" and a 504 means "no response within the time limit". Mixing them wastes hours. Also, the response to an OOM is completely different depending on its kind (Java heap space / Metaspace / unable to create native thread), so if you raise only -Xmx without reading the message, things can actually get worse. If you have hands that can pull numbers from logs, this judgment turns from guesswork into evidence.

Steps

Create /root/ts and copy the four files in /opt/lab/fixtures/tomcat/logs/ as they are. (catalina-oom.log, gc.log, access.log, nginx-error.log) The contents must be identical to the originals.
Find OutOfMemoryError in catalina-oom.log and create /root/ts/oom.txt. It has two lines and the format is exactly as below.
```
time=<로그에 적힌 타임스탬프>
type=<OOM 종류 문자열>
```
type is one of Java heap space / Metaspace / GC overhead limit exceeded / unable to create native thread.

Analyze gc.log and create /root/ts/gc.txt. It has two lines.

fullgc=<Full GC 발생 횟수>
maxpause=<가장 긴 정지 시간, 밀리초, 소수점 포함 그대로>

From access.log, extract the top 5 URLs by long processing time and create /root/ts/slow.csv. The first line is url,count,max_ms, sorted by max_ms in descending order.
From access.log, aggregate the 5xx responses by URL and create /root/ts/5xx.csv. The first line is url,status,count, sorted by count in descending order.
From nginx-error.log, aggregate upstream errors by cause and create /root/ts/upstream.csv. The first line is code,cause,count. code is 502 or 504, and cause is connection refused or timeout.
Start Tomcat, take a thread dump and save it to /root/ts/threads.txt, then create /root/ts/threadstat.txt. It has two lines.
```
total=<덤프에 있는 전체 스레드 수>
waiting=<WAITING 상태 스레드 수>
```
The two values must match the contents of threads.txt.
Write /root/ts/rca.md. It must have four h2 headings, ## 현상, ## 원인, ## 조치 and ## 재발방지, and the OOM type string from step 2 and the fullgc number from step 3 must be quoted as they are in the body.

Notes

Maximum per URL: awk -F'|' '{ if ($3 > m[$2]) m[$2]=$3; c[$2]++ } END {...}'
Thread dump: jcmd <PID> Thread.print > /root/ts/threads.txt
Number of threads in the dump: a line starting with a double quote is one thread.
Common mistake 1: counting Young GCs as well when counting Full GCs.
Common mistake 2: using lexicographic sorting instead of sort -n, so that 9.5 comes out larger than 12.3.
Common mistake 3: writing only "memory ran out" in the report, with no numbers.

Secure a copy of the logs

Create /root/ts and copy the four files in /opt/lab/fixtures/tomcat/logs/ as they are. (catalina-oom.log, gc.log, access.log, nginx-error.log) The contents must be identical to the originals.

The first action in incident analysis is preserving the originals. Logs being rotated or overwritten during analysis really happens.

Check the time and kind of the OOM

Find OutOfMemoryError in catalina-oom.log and create /root/ts/oom.txt. It has two lines and the format is exactly as below.

time=<로그에 적힌 타임스탬프>
type=<OOM 종류 문자열>

type is one of Java heap space / Metaspace / GC overhead limit exceeded / unable to create native thread.

The response to an OutOfMemoryError is completely different by kind. The kind is written in the latter part of the message.

Analyze the GC log

Analyze gc.log and create /root/ts/gc.txt. It has two lines.

fullgc=<Full GC 발생 횟수>
maxpause=<가장 긴 정지 시간, 밀리초, 소수점 포함 그대로>

You must count only Full GCs. The pause time is the millisecond value at the end of each line. There are decimal points, so be careful with the sorting method.

Extract the slowest URLs

From access.log, extract the top 5 URLs by long processing time and create /root/ts/slow.csv. The first line is url,count,max_ms, sorted by max_ms in descending order.

The last field of the access log is the processing time. You have to group by URL and get the maximum. If you use awk's associative arrays, one scan is enough.

Distribution of 5xx occurrences

From access.log, aggregate the 5xx responses by URL and create /root/ts/5xx.csv. The first line is url,status,count, sorted by count in descending order.

You have to point precisely at the status code field. Pick only the three-digit codes starting with 5 and aggregate by URL.

Tell apart the causes of 502 and 504

From nginx-error.log, aggregate upstream errors by cause and create /root/ts/upstream.csv. The first line is code,cause,count. code is 502 or 504, and cause is connection refused or timeout.

The wording in the nginx error log tells you the cause. A connection being refused itself and a time limit being exceeded are left with different wording.

Analyze a real thread dump

Start Tomcat, take a thread dump and save it to /root/ts/threads.txt, then create /root/ts/threadstat.txt. It has two lines.

total=<덤프에 있는 전체 스레드 수>
waiting=<WAITING 상태 스레드 수>

The two values must match the contents of threads.txt.

Take a dump from the running Tomcat and count the threads by state. In the dump, the thread state appears as an uppercase keyword.

Write the incident report

Write /root/ts/rca.md. It must have four h2 headings, ## 현상, ## 원인, ## 조치 and ## 재발방지, and the OOM type string from step 2 and the fullgc number from step 3 must be quoted as they are in the body.

The value of the report is in the numbers. Quote exactly the values you pulled in the earlier steps. In the prevention items, instead of 'be careful', write concrete settings or monitoring items.