커널도 소프트웨어이기 때문에 일반적인 어플리케이션에서 발생하는 메모리 할당 오류(segfault)등의 문제가 발생할 수 있다. 커널은 OS의 핵심이므로 어플리케이션의 오류보다 심각한 결과를 초래할 수 있다. 따라서 중요한 시스템의 경우 Kernel Panic이 발생을 한다면 원인 분석과 그에 따른 조치가 꼭 필요로 된다.

리눅스에서 어플리케이션 덤프를 gdb를 통해 분석하 듯 커널 덤프 파일인 vmcore도 gdb 기반의 crash 유틸리티를 이용하여 분석할 수 있다. 하지만 커널 패닉 당시의 메모리 덤프 파일인 vmcore를 정확히 분석하는 일은 쉽지 않은 일이다. 디테일한 분석을 위해서는 커널의 매커니즘과 C언어 코드를 분석할 수 있는 능력도 필요로 된다. 단순히 리눅스를 운영관리할 수 있는 수준으로는 범접하기 쉽지 않은 영역이지만 몇가지 분석툴과 구글링을 이용한다면 원인에 근접할 수 있게 범위를 좁힐 수는 있다.

 

0. Linux Crash 란 ?

Crash 란 시스템이 정지 (Halt) 하거나 더 이상 프로세스 진행이 모니터링 되지 않거나 할 때 일컬어지는 일반적인 용어. 또한 시스템이 응답하지 않거나 알 수 없는 이유로 이미 리부팅이 되었을 때도 해당 용어가 사용됨.

Linux 에서 Crash 는 다음과 같은 여러 유형이 있다.

1) Panic - 비정상적인 상황이 커널에 의해 검출 (detected) 되었을 때 모든 시스템 활동이 스스로 정지되는 장애를 의미함.

2) Oops - panic 과 비슷하나 커널이 시스템 상황 (situation) 이 비정상적이지 않다고 판단될 경우 문제유발을 발생시키는 프로세스를 종료하고 시스템을 계속 운영하는 장애를 의미함 .

3) BUG() - panic 과 비슷하나 비정상적인 상태 (abnormal conditions) 를 검사하기 위해 의도적인 코드를 호출하여 문제원인을 파악하기 위한 장애를 의미함.

4) Hang - 시스템에서 더 이상의 프로세스가 운영되지 않는 장애를 의미하며 soft 또는 hard 두 가지 장애로 구분됨.

 

1. 준비물

1.1. debuginfo 패키지

- kdump에 의해 수집된 vmcore에 맞는 커널 버전의 debuginfo 파일 필요

debuginfo는 kernel에 대한 debug 정보를 포함하여 컴파일한 패키지 임.

# yum localinstall -y kernel-debuginfo-2.6.32-504.el6.x86_64.rpm

(해당 패키지는 OS 기본 DVD 이미지에 포함되어 있지 않다.)

1.2. crash 유틸리티

- 덤프 분석을 위한 유틸리티.

- gdb와 유사하지만 gdb로 분석이 용이하지 않은 점을 감안해 만들어진 linux kernel core dump 전용 분석 툴이다.

1.3. 커널 소스 코드

분석 시 참조할 커널 소스

1.4. sosreport 파일

- 각종 로그와 S/W, H/W 정보 등이 포함된 sosreport 파일

- 직접 운영하는 서버를 분석하는 경우가 아니라면 더욱더 필요하다.

1.5. 환경 변화 파악

한참 잘 돌아가던 시스템이 어느 날 갑자기 커널 패닉이 발생을 했다면 최근의 어떠한 변화가 원인이 될 가능성이 크다.

- 서버의 환경 파악과 core dump가 발생하기 전에 서버 변경 작업이 있었는지 확인.

- 하드웨어, 서드파티 모듈 변화 등을 체크.

1.6. 노하우

다양한 경험을 통해 길러진 숲을 볼 줄 하는 혜안이 필요하다.

 

2. kernel panic 발생 시키기

테스트 분석을  위해 커널 패닉을 강제로 발생 시킨다.

먼저 kdump 설정이 되어 있어야 된다. kdump 설정은 여기를 참조할 것 : 여기

커널 분석을 위한 vmcore 수집을 위해 magic key를 이용하는 방법도 있지만 여기서는

간단한 c 코드로 null pointer를 참조하는 커널 모듈을 만들어 커널패닉을 발생시키도록 한다.

 

사전에 설치할 패키지

# yum install -y make gcc kernel-devel

2.1. c 코드

# vi /root/null-pointer.c

/*
 *  null-pointer.c - A not so simple kernel module to crash kernel.
 */

#include <linux/module.h>    /* Needed by all modules */
#include <linux/kernel.h>    /* Needed for KERN_INFO */

char *p=NULL;

int init_module(void)
{
    printk(KERN_INFO "We is gonna KABOOM now!\n");

    *p = 1;
    return 0;
}

void cleanup_module(void)
{
    printk(KERN_INFO "Goodbye world.\n");
}

2.2. Makefile 작성

# vim /root/Makefile

KERNELDIR=/lib/modules/2.6.32-504.el6.x86_64/build

obj-m+= null-pointer.o

KDIR:=/lib/modules/2.6.32-504.el6.x86_64/build
PWD := $(shell pwd)

default :
        make -C /lib/modules/$(shell uname -r)/build M=$(PWD) modules

clean :
        rm -f *.ko
        rm -f *.mod.*
        rm -f .*.cmd
        rm -f *.o
        rm -f *.ko.unsigned

* 주의점은 default 항목 아래의 make 구문 앞은 tab 공백이 들어가야 한다.

그렇지 않으면 아래와 같이 make가 되지 않는다.

make: Nothing to be done for `default'.

마찬가지로 clean 항목 아래에도 tab 공백을 사용. 그렇지 않으면 make clean 시에도 에러 발생.

Makefile:13: *** missing separator.  Stop.

스페이스 공백으로 들여쓰기를 하면 vim에서 구문이 아래와 같이 빨간색으로 표기 됨.

Cap 2015-07-08 20-44-18-732

탭 공백으로 들여쓰기를 하면 vim에서 구문이 아래와 같이 표기 됨.

Cap 2015-07-08 20-44-24-819

 

2.3. make

Cap 2015-07-08 21-23-59-150

null-pointer.ko 커널모튤 파일 생성이 됐다.

- 모듈 정보 확인

Cap 2015-07-08 21-26-12-171

2.4. 모듈 로딩

# insmod null-pointer.ko

명령을 내리자 마자 커널 패닉 발생과 함께 kexec에 의해 예약해둔 메모리에 임시 커널이미지인 initrd-2.6.32-504.el6.x86_64kdump.img 를 올린다.

아래는 임시 커널을 올리는 순간의 콘솔 화면을 캡쳐한 이미지 이다. 참고로 커널패닉 시 콘솔출력은 init 3 이하 모드에서만 확인이 된다.

Cap 2015-07-08 21-28-08-797

 

2.5. vmcore 확인

vmcore가 수집되고 /etc/kdump.conf에 명시된 대로 시스템이 reboot 된다.

- default가 reboot 이다. 만약 halt 상태로 두고 싶으면 kdump.conf에 halt로 설정하면 된다.

- kdump.conf 에 명시된 /var/crash (default)에 127.0.0.1-time 형태의 디렉토리가 생성.

# cd /var/crash/127.0.0.1-2015-07-08-21:28:27

# ll
total 31944
-rw------- 1 root root 32611600 Jul 8 21:28 vmcore
-rw-r--r-- 1 root root 90512 Jul 8 21:28 vmcore-dmesg.txt

-> vmcore-dmesg.txt 파일은 패닉 당시의 dmesg 내용으로, 마지막 부분에 oops, Call Trace, RIP 정보 등이 포함한다. 이 메시지만으로도 어떠한 사유로 시스템이 뻗었는지 짐작을 할 수 있다. dmesg는 crash 유틸리티에서 log 라는 명령으로도 확인이 가능하다.

-> 만약 어떠한 이유(/var/crash 용량, 예약된 메모리량이 작아서.. 등등..)에 의해서 vmcore 수집이 완료되지 못 하면 vmcore 파일명이 아닌 vmcore-incomplete 이름으로 생성이 된다.

# crash -d1 vmcore | grep release
release: 2.6.32-504.el6.x86_64

참고로 RHEL 4 버전에서는 vmcore 파일의 커널 버전을 아래처럼 확인할 수 있었다.

# string vmcore | fgrep -m1 'Linux' 

 

2.6. 분석

crash> gdb 상의 명령어 모음

sys - 시스템의 일반적인 정보를 출력해 준다.
bt - Backtrace 명령. 스택의 내용들을 순차적으로 출력해준다.
ps - Process list 출력.
free - Memory 및 스왑 상태 출력.
mount - 마운트 상태 출력
irq - 각 장치의 ( irq ) 상태를 출력.
kmem - 메모리 상태 출력 ( kmalloc, valloc 등 메모리 할당 상태도 보여줌 )
log - dmesg 의 내용을 출력.
mod - 로딩된 모듈 리스트 출력.
net - Network 상태 출력.
runq - 실행중인 task 리스트 출력.
task - 작업목록 출력.
rd - 메모리 번지수에 대한 상세정보 출력.
foreach - 모든 task, process 등 디버깅 정보에 대한 상세한 출력이 가능함.
set - 설정된 주소 및 PID 등을 기본 컨텍스트로 설정.
struct - 구조화된 메모리 내부의 변수들을 출력해 준다.
files - task 가 열고있는 파일디스크립터들을 출력해준다.

# crash /usr/lib/debug/lib/modules/2.6.32-504.el6.x86_64/vmlinux vmcore

Cap 2015-07-22 11-32-25-831

 

PANIC: "Oops: 0002 [#1] SMP " (check log for details)

CPU 1에서  Oops 메시지와 함께 0002 dec Code 발생.

0002 (dec) 를 binary로 변환하면 0010이 된다.

Kernel Page Error 를 살펴 보면 아래와 같다.

The four digits are a decimal code of the Kernel Page Error. Reading O'Reilly's Understanding Linux Kernel, Chapter 9: Process Address Space, Page Fault Exception Handler, pages 376-382, we learn the following information:

If the first bit is clear (0), the exception was caused by an access to a page that is not present; if the bit is set (1), this means invalid access right.
If the second bit is clear (0), the exception was caused by read or execute access; if set (1), the exception was caused by a write access.
If the third bit is clear (0), the exception was caused while the processor was in Kernel mode; otherwise, it occurred in User mode.
The fourth bit tells us whether the fault was an Instruction Fetch. This is only valid for 64-bit architecture. Since our machine is 64-bit, the bit has meaning here.

crash-analysis-kpe-vertical

 

0010 을 위 표에 대입하면

0002 (dec) --> 0010 (binary) --> Not instruction fetch|Kernel mode|Write|Page not found

Therefore, we have a page not found during a write operation in Kernel mode; the fault was not an Instruction Fetch.

(커널 모드에서 쓰기를 하는 동안 페이지를 찾을 수 없어서 명령어 인출을 하지 못 하고 fault 발생)

* Page (페이지) : 가상 기억장치와 물리 기억장치 사이에 매핑이 이루어지는 단위.

* Instruction Fetch (명령어 인출) : CPU가 한 명령어의 실행을 끝내고 다음에 실행될 명령어를 기억 장치에서 꺼내올 때까지의 동작 단계.

 

- 로그를 찍어보자

crash> log
~~ 생략 ~~
Pid: 6951, comm: insmod Tainted: P --------------- H 2.6.32-279.el6.x 86_64 #1 VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform
RIP: 0010:[<ffffffffa001903e>] [<ffffffffa001903e>] init_module+0x1e/0x28 [null _pointer]
RSP: 0018:ffff88007b23bf18 EFLAGS: 00010292
RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000000
RDX: 0000000000000000 RSI: 0000000000000046 RDI: 0000000000000246
RBP: ffff88007b23bf18 R08: 000000000001394a R09: 4b20616e6e6f6720
R10: 4f42414b20616e6e R11: 0a21776f6e204d4f R12: ffffffffa0019020
R13: 0000000001bcb010 R14: 0000000001bcb030 R15: 0000000000000003
FS: 00007fe6a2458700(0000) GS:ffff880002200000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
CR2: 0000000000000000 CR3: 000000007a59d000 CR4: 00000000000406f0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Process insmod (pid: 6951, threadinfo ffff88007b23a000, task ffff8800372b8080)
Stack:
 ffff88007b23bf48 ffffffff8100204c 0000000001bcb030 ffffffffa00190c0
<d> 000000000001a4a7 0000000001bcb010 ffff88007b23bf78 ffffffff810b0d71
<d> 000000000001a4a7 00007fff764638ba 000000000001a4a7 0000000000020000
Call Trace:
 [<ffffffff8100204c>] do_one_initcall+0x3c/0x1d0
 [<ffffffff810b0d71>] sys_init_module+0xe1/0x250
 [<ffffffff8100b0f2>] system_call_fastpath+0x16/0x1b
Code: cb 41 4e e1 c9 c3 0f 1f 80 00 00 00 00 55 48 89 e5 0f 1f 44 00 00 48 c7 c7 7f 90 01 a0 31 c0 e8 ab 41 4e e1 48 8b 05 b2 02 00 00 <c6> 00 01 31 c0 c9 c3 90 90 90 04 00 00 00 14 00 00 00 03 00 00
RIP [<ffffffffa001903e>] init_module+0x1e/0x28 [null_pointer]
 RSP <ffff88007b23bf18>
CR2: 0000000000000000

RIP  [<ffffffffa001903e>] init_module+0x1e/0x28 [null_pointer] 를 주목하자.

 

- 패닉 직전 메모리 사용량은 높진 않았음.

crash> kmem -i
              PAGES        TOTAL      PERCENTAGE
 TOTAL MEM   317071       1.2 GB         ----
      FREE   219349     856.8 MB   69% of TOTAL MEM
      USED    97722     381.7 MB   30% of TOTAL MEM
    SHARED     9049      35.3 MB    2% of TOTAL MEM
   BUFFERS     3931      15.4 MB    1% of TOTAL MEM
    CACHED    43854     171.3 MB   13% of TOTAL MEM
      SLAB    15240      59.5 MB    4% of TOTAL MEM

TOTAL SWAP  1032190       3.9 GB         ----
 SWAP USED        0            0    0% of TOTAL SWAP
 SWAP FREE  1032190       3.9 GB  100% of TOTAL SWAP

 

- 패닉 직전 실행된 명령은 insmod 이다. insmod 명령을 통해서 panic이 발생된 것이 확인된다.

crash> runq
CPU 0 RUNQUEUE: ffff880002216680
  CURRENT: PID: 6951   TASK: ffff8800372b8080  COMMAND: "insmod"
  RT PRIO_ARRAY: ffff880002216808
     [no tasks queued]
  CFS RB_ROOT: ffff880002216718
     [no tasks queued]

CPU 1 RUNQUEUE: ffff880002316680
  CURRENT: PID: 0      TASK: ffff88007dd33540  COMMAND: "swapper"
  RT PRIO_ARRAY: ffff880002316808
     [no tasks queued]
  CFS RB_ROOT: ffff880002316718
     [no tasks queued]

 

crash> ps | grep '>'
>     0      0   1  ffff88007dd33540  RU   0.0       0      0  [swapper]
>  6951   6561   0  ffff8800372b8080  RU   0.0    4048    488  insmod

 

- bt -t 로 확인해 찍어보니 insmod 명령을 통해 null_pointer 모듈이 로딩 되었던것이 확인 되었다.

crash> bt -t
PID: 6951   TASK: ffff8800372b8080  CPU: 0   COMMAND: "insmod"
              START: machine_kexec at ffffffff8103281b
  [ffff88007b23bae0] machine_kexec at ffffffff8103281b
  [ffff88007b23bb40] crash_kexec at ffffffff810ba662
  [ffff88007b23bb60] init_module at ffffffffa0019020 [null_pointer]
  [ffff88007b23bbc8] init_module at ffffffffa001903e [null_pointer]
  [ffff88007b23bc10] oops_end at ffffffff81501290
  [ffff88007b23bc40] no_context at ffffffff81043bab
  [ffff88007b23bc50] idr_get_empty_slot at ffffffff81272cd0
  [ffff88007b23bc90] __bad_area_nosemaphore at ffffffff81043e35
  [ffff88007b23bce0] bad_area at ffffffff81043f5e
  [ffff88007b23bd10] __do_page_fault at ffffffff81044710
  [ffff88007b23bd50] vsnprintf at ffffffff8127ca36
  [ffff88007b23bda0] up at ffffffff81097e2f
  [ffff88007b23bdb0] probe_kernel_write at ffffffff81118021
  [ffff88007b23bdd0] release_console_sem at ffffffff8106bfdf
  [ffff88007b23be30] do_page_fault at ffffffff8150326e
  [ffff88007b23be40] init_module at ffffffffa0019020 [null_pointer]
  [ffff88007b23be60] page_fault at ffffffff81500625
  [ffff88007b23be80] init_module at ffffffffa0019020 [null_pointer]
  [ffff88007b23bee8] init_module at ffffffffa001903e [null_pointer]
  [ffff88007b23bf10] init_module at ffffffffa0019037 [null_pointer]
  [ffff88007b23bf20] do_one_initcall at ffffffff8100204c
  [ffff88007b23bf50] sys_init_module at ffffffff810b0d71
  [ffff88007b23bf80] system_call_fastpath at ffffffff8100b0f2
    RIP: 000000353e0e7cea  RSP: 00007fff76463080  RFLAGS: 00010206
    RAX: 00000000000000af  RBX: ffffffff8100b0f2  RCX: 0000000000020030
    RDX: 0000000001bcb010  RSI: 000000000001a4a7  RDI: 0000000001bcb030
    RBP: 0000000001bcb010   R8: 0000000000000001   R9: 0000000000000001
    R10: 000000353e0da300  R11: 0000000000000206  R12: 0000000000020000
    R13: 000000000001a4a7  R14: 00007fff764638ba  R15: 000000000001a4a7
    ORIG_RAX: 00000000000000af  CS: 0033  SS: 002b

 

문제의 과정을 살펴보면, insmod 명령을 통해 커널 모듈을 로드함 -> 그런데 그것은 어떤 page에 write를 시도했으나 그 페이지를 찾을 수 없었고 시스템을 보호하기 위해 crash가 발생되었다. 따라서 insmod 하려 했던 ko (커널 모듈)의 코드의 버그 가능성이 크다.

그럼 이제 문제의 null-pointer.ko 을 분석해 보자.

objdump를 통해 바이너리 null-pointer.ko(커널 모듈) 바이너리 파일에서 역어셈블을 해보면 아래와 같은 코드를 확인해 볼 수 있다.

# objdump -d -S /tmp/null-pointer.ko > /tmp/null-pointer.whatever

# cat /tmp/null-pointer.whatever

/root/null-pointer.ko:     file format elf64-x86-64


Disassembly of section .text:

0000000000000000 <cleanup_module>:
    *p = 1;
    return 0;
}

void cleanup_module(void)
{
   0:   55                      push   %rbp
   1:   48 89 e5                mov    %rsp,%rbp
   4:   e8 00 00 00 00          callq  9 <cleanup_module+0x9>
    printk(KERN_INFO "Goodbye world.\n");
   9:   48 c7 c7 00 00 00 00    mov    $0x0,%rdi
  10:   31 c0                   xor    %eax,%eax
  12:   e8 00 00 00 00          callq  17 <cleanup_module+0x17>
}
  17:   c9                      leaveq
  18:   c3                      retq
  19:   0f 1f 80 00 00 00 00    nopl   0x0(%rax)

0000000000000020 <init_module>:
#include <linux/kernel.h>    /* Needed for KERN_INFO */

char *p=NULL;

int init_module(void)
{
  20:   55                      push   %rbp
  21:   48 89 e5                mov    %rsp,%rbp
  24:   e8 00 00 00 00          callq  29 <init_module+0x9>
    printk(KERN_INFO "We is gonna KABOOM now!\n");
  29:   48 c7 c7 00 00 00 00    mov    $0x0,%rdi
  30:   31 c0                   xor    %eax,%eax
  32:   e8 00 00 00 00          callq  37 <init_module+0x17>

    *p = 1;
  37:   48 8b 05 00 00 00 00    mov    0x0(%rip),%rax        # 3e <init_module+0x1e>
  3e:   c6 00 01                movb   $0x1,(%rax)
    return 0;
}
  41:   31 c0                   xor    %eax,%eax
  43:   c9                      leaveq
  44:   c3                      retq
  45:   90                      nop
  46:   90                      nop
  47:   90                      nop

37 라인의# 3e <init_module+0x1e> 를 보면 3e가 확인 되고,

3e 라인 - 어셈블리 movb의 1($0x1) 값을 %rax 에 접근하려 함.

그런데 위에서 확인한 log 의 RAX 값은 null 인 것이다.

RAX register is: 0000000000000000

이로서 null pointer 에 접근한 것임이 밝혀짐.

일반적으로 OS는 메모리의 첫 페이지 주소 0(0x00000000)를 사용하는데, 이 영역을 null-pointer.ko 모듈이 로딩되면서 침범하였고 그로인해 시스템을 보호하기 위해 kernel crash가 발생되고 kdump에 의해 vmcore가 수집된 것이다.

 

- null pointer ?

C 나 C++ 에서 null pointer는 '어떠한 것도 가리키지 않는 포인터' 또는 '할당되지 않은' 것을 의미하는 특별한 포인터로 쓰인다. 대부분의 운영체제에서는 이 null pointer를 메모리의 첫 페이지 주소 0(0x00000000)로 사용하고 있다. 따라서 여기에 접근하면 보통 프로그램이 비정상적으로 종료된다.

 

이상이다.

vmcore analyze

“vmcore analyze”에 대한 1개의 생각

답글 남기기

이메일 주소는 공개되지 않습니다. 필수 필드는 *로 표시됩니다