revenge1005 🧗

[시스템 관리] 06. 로그 감시법

Date:     Updated:

카테고리:

태그:


🔔 로그 감시법


■ 시각으로 범위를 좁힌다.

  1. 로그 확인 시, 장애가 발생한 시각 부근의 메시지를 확인한다.

  2. cat, less 명령 대신 tail 또는 head를 사용하여 파일의 일부만 출력하여 시스템 부하를 줄일 수 있고, nice나 ionice와 같은 낮은 우선순위로 실행하면 부하를 더 낮출 수 있다.

  3. 로그를 확인할 때 모든 메시지가 장애 원인은 아니라는 점을 주의해야 한다.

  4. 장애 전후로 계속 나오는 메시지는 노이즈(장애와 직접 관계가 없는 메시지)일 수 있다.

  5. 노이즈를 제외하고 추출 대상을 확인하기 위해서는 grep의 -v 옵션(검색 패턴과 일치하지 않는 라인을 출력)을 사용하는 것이 좋다.

# 예시용 /var/log/messages 내용
Jun 4 20:00:01 Server dhclient: DHCPREQUEST on eth0 to 192.168.1.1
Jun 4 20:01:10 Server kernel: Error - Connection timeout
Jun 4 20:02:22 Server app: Application started
Jun 4 20:02:45 Server dhclient: DHCPACK from 192.168.1.1
Jun 4 20:03:05 Server app: Error - Database connection failed
Jun 4 20:03:40 Server dhclient: bound to 192.168.1.100 -- renewal in 500 seconds.
Jun 4 20:04:15 Server app: Error - Invalid input data
Jun 4 20:04:58 Server dhclient: DHCPREQUEST on eth0 to 192.168.1.1
Jun 4 20:05:25 Server kernel: Error - Disk I/O error

# 예시 1)
$ tail -n 1000 /var/log/messages | grep "Jun 4 20:0[0-5]"
# 또는
$ nice -n 19 ionice -c3 tail -n 1000 /var/log/messages | grep "Jun 4 20:0[0-5]"

Jun 4 20:02:22 Server app: Application started
Jun 4 20:02:45 Server dhclient: DHCPACK from 192.168.1.1
Jun 4 20:03:05 Server app: Error - Database connection failed
Jun 4 20:03:40 Server dhclient: bound to 192.168.1.100 -- renewal in 500 seconds.
Jun 4 20:04:15 Server app: Error - Invalid input data

# 예시 2)
$ tail -n 1000 /var/log/messages | grep "Jun 4 20:0[0-5]" | grep -v "dhclient"

Jun 4 20:02:22 Server app: Application started
Jun 4 20:03:05 Server app: Error - Database connection failed
Jun 4 20:04:15 Server app: Error - Invalid input data


■ 키워드로 범위를 좁힌다.

  1. 시각으로만 범위를 좁히는 것은 대량의 로그가 출력된 경우에는 효과적이지 않을 수 있으므로, 키워드를 사용하여 범위를 좁힌다.

  2. 장애 원인을 추측할 수 있다면, 해당 장애 발생 시 출력되는 문자열을 미리 알아두고, 이를 바탕으로 검색하는 것이 빠를 수 있지만 검색 문자열이 구체적이면 다른 메시지까지 필터링될 수 있으므로 이 방법은 사전 연습 정도로만 이용하는 것이 좋다.

  3. 미지의 오류 발생 시 자주 출력되는 로그 레벨 문자열을 키워드로 사용하는 것이 좋다. 일반적인 로그 레벨 문자열은 다음과 같다.

    로그 레벨 의미
    Fatal, Critical 치명적인 오류 장애
    Error 치명적인 오류 정보 또는 오류 정보
    Warning 경고 정보
    Info, Note, Notice 일반적인 (조작) 정보
    Debug, Trace 디버그 정보

  4. 로그 레벨 문자열은 소프트웨어별로 약간씩 다르므로, 로그 레벨의 사양을 파악하거나 찾기 쉬운 패턴을 지정해야 한다. (예시: warn(약자 표기), warning(소문자 표기))

  5. 검색에서 쉽게 찾을 수 있도록 grep의 -i 옵션(대소문자를 구별하지 않고 검색)을 사용하는 것이 좋다.

# 예시용 /var/log/httpd/error_log 내용
[Jun 4 20:05:10] [error] [client 192.168.1.100] server reached MaxClients, shutting down
[Jun 4 20:06:15] [warn] [client 192.168.1.101] Request header is too large
[Jun 4 20:06:30] [info] [client 192.168.1.102] Successfully connected to database
[Jun 4 20:07:05] [error] [client 192.168.1.103] File not found: /var/www/html/page.html
[Jun 4 20:08:20] [warn] [client 192.168.1.104] Connection timeout to server

# 예시 1)
$ tail -n 1000 /var/log/httpd/error_log | grep "server reached MaxClients"

[Jun 4 20:05:10] [error] [client 192.168.1.100] server reached MaxClients, shutting down

# 예시 2)
$ tail -n 1000 /var/log/httpd/error_log | grep -i "warn"

[Jun 4 20:06:15] [warn] [client 192.168.1.101] Request header is too large
[Jun 4 20:08:20] [warn] [client 192.168.1.104] Connection timeout to server


■ 메시지 양을 주목한다.

  1. 서비스에 문제가 생겼지만 오류 메시지에 아무것도 출력되지 않는 경우, 요청 대비 시스템 처리 성능이 부족한 것이 원인일 수 있으므로 메시지 양을 비교하여 확인해야 한다.

  2. 시각별로 액세스 로그를 집계하면 액세스 증감을 알 수 있으며, uniq -c의 결과를 가시화하는 도구인 Cacti나 Munin과 같은 감시 도구를 사용하여 데이터를 쉽게 시각화할 수 있다.

  3. 액세스한 소스 IP 주소별로 집계하면 어떤 IP 주소에서 액세스가 많았는지 알 수 있으며, 특정 IP 주소의 접속이 극단적으로 많을 경우, 부정 액세스나 검색 엔진 로봇에 의한 스캔일 수 있으므로 주의해야 한다.

  4. 메시지 양을 비교하는 대상은 신중해야 하는데, 할인판매 등으로 인해 하루 중 액세스가 많은 경우, 수 분 전의 메시지양과 비교하더라도 액세스 증가라고 판단할 수 없으며 사흘 전, 일주일 전과 같이 일반적인 액세스 상황과 비교하여 판단하는 것이 중요하다.

  5. 서비스 사용자가 증가하면서 액세스가 많아지는 경우, 서버 튜닝이나 스펙업으로 대처해야 한다.

# 예시 1)
$ tail -10000 access_log | grep "05/jun/2014" | cut -d ':' -f 2,3 | sort | uniq -c

    383 09:35
   3253 09:36
   1120 09:37
   1196 09:38
    933 09:39
    355 09:40
    348 09:41
    219 09:42
    370 09:43
    218 09:44
    313 09:45 

# 예시 2)
$ tail -10000 access_log | grep "05/jun/2014:09:36" | awk '{print $1}' | sort -n | uniq -c | sort

    6 198.51.10.1
    8 198.51.10.2
   34 198.51.10.3
   40 198.51.10.4 
  130 198.51.10.5 
 3000 198.51.10.6


■ 현장에서 장애 원인을 판별하는 예시

  1. MySQL 서버가 갑자기 정지하는 장애가 발생했다고 가정했을 때, 가장 먼저 확인할 것은 MySQL의 “오류 로그”이다.
# 예시 1) /var/lib/mysql/test.com.err 
01 140612 20:42:09 mysqld_safe Number of processes running now: 0                      ## mysqld_safe가 mysqld 프로세스 개수가 0임을 확인
02 140612 20:42:09 mysqld_safe mysqld restarted                                        ## mysql를 재시작 (이미 이 시점에 종료되어 있음)
03 140612 20:42:15 [Note] Plugin 'FEDERATED' is disabled.
04 140612 20:42:15 InnoDB: The InnoDB memory heap is disabled
05 140612 20:42:15 InnoDB: Mutexes and rw_locks use GCC atomic builtins
06 140612 20:42:15 InnoDB: Compressed tables use zlib 1.2.7
07 140612 20:42:15 InnoDB: Using Linux native AIO
08 140612 20:42:15 InnoDB: Initializing buffer pool, size = 256.0M
09 InnoDB: mmap(274726912 bytes) failed; errno 12
10 140612 20:42:15 InnoDB: Completed initialization of buffer pool
11 140612 20:42:15 InnoDB: Fatal error: cannot allocate memory for the buffer pool 2   ## "Fatal error". buffer pool용 메모리 확보에 실패
12 140612 20:42:15 [ERROR] Plugin 'InnoDB' init "function returned error."
13 140612 20:42:15 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.    ## InnoDB 등록 실패
14 140612 20:42:15 [ERROR] Unknown/unsupported storage engine: InnoDB
15 140612 20:42:15 [ERROR] Aborting                                                    ## 비정상 종료
16 140612 20:42:15 [Note] /usr/libexec/mysqld: Shutdown complete                       ## mysqld 정지
17 140612 20:42:15 mysqld_safe mysqld from pid file /var/run/mysqld/mysqld.pid ended

  1. 여기서는 MySQL이 정지한 것이 문제이므로 관련이 있을 만한 로그를 중심으로 봐야하며, ERROR나 FATAL과 같은 문자열도 그냥 넘기지 말고 확인해야 한다.

  2. 이미 01줄의 로그 출력 단계에서 mysqld가 종료되어 있으므로 MySQL의 로그를 확인하는 것만으로는 근본적인 원인이 명확하지 않은 상태이다.

  3. 02줄에서는 메모리를 확보할 수 없어 실패했다는 걸 알려준다.

  4. 지금부터는 예측이지만 어쩌면 처음으로 프로세스가 종료한 원인도 메모리와 관련이 있을 수 있다. 따라서 MySQL 로그에서 확인된 시각보다 이전 시점의 시스템 로그(/var/log/messages)를 확인한다.

# 예시 2) /var/og/messages
01 Jun 12 20:42:05 www kernel: [29204168.349016] httpd invoked oom-killer: gfp_mask=0x201da, order=0, oom_ score_adj=0
02 Jun 12 20:42:05 www kernel: [29204168.349033] httpd cpuset=/ mems_allowed=0
03 Jun 12 20:42:05 www kernel: [29204168.349077] Call Trace:
04 Jun 12 20:42:05 www kernel: [29204168.349090] [<ffffffff8143eb2b>] dump_stack+0x19/0x1b
05 Jun 12 20:42:05 www kernel: [29204168.349108] [<ffffffff814449ba>] 7 error_exit+0x2a/0x60
06 Jun 12 28:42:85 www kernel: [29284168.349126] [<ffffffff814444bb>] ? retint_ restore_args+ax5/0x6
07 Jun 12 20:42:05 www kernel: [29204168.349137] [<ffffffff811191e>] oom_kill_process+8x1a9/0x310
08 Jun 12 20:42:05 www kernel: [29284168.349153] [<ffffffff81208495>] 7 security_ capable_noaudit+0x15/0x20
09 Jun 12 20:42:05 www kernel: [29204168.349161] [<ffffff81119939>] out_of_memory+0x429/0x460
10 ...
11 Jun score 12 78 or 20:42:05 www kernel: [29204168. 573052] out of memory: Kill process 19632 (mysqld) score 78 or sacrifice child
12 Jun 12 28:42:05 www kernel: [29284168.573068] Killed process 19632 (mysqld) totalvm:1542800kB, anon-rss:132188kB, file-rss:ekB ## mysqld 강제 종료
  1. 시스템 로그에서 OOM Killer(Out Of Memory Killer)에 의해 mysqld가 강제로 종료되었음을 확인한다.

SYS_MGMT 카테고리 내 다른 글 보러가기

댓글 남기기

최근 글 10 개 :)