커널패닉 - ext4 파일 시스템

커널 패닉 한번 분석 좀 해보자.

패닉 로그는 아래와 같다.  오라 ext4 파일 시스템에서 커널님이 돌아가셨구나. 돌아가실 때 프로세스 이름은 system_server이며 대략, ext4 파일 시스템에서 아이노드를 free하다가 죽었다는 것을 알 수 있다.
[   34.187856 01-05 13:30:49.424] Unable to handle kernel NULL pointer dereference at virtual address 00000000
[   34.197812 01-05 13:30:49.434] pgd = e6f9c000
[   34.202275 01-05 13:30:49.438] [00000000] *pgd=00000000
[   34.207610 01-05 13:30:49.444] Internal error: Oops: 5 [#1] PREEMPT SMP ARM
[   34.214663 01-05 13:30:49.451] Modules linked in: bcmdhd(O)
[   34.220400 01-05 13:30:49.457] CPU: 0    Tainted: G        W  O  (3.4.65-gbc0bf75 #1)
[   34.228317 01-05 13:30:49.464] PC is at ext4_free_inode+0x288/0x574
[   34.234664 01-05 13:30:49.471] LR is at ext4_free_inode+0x260/0x574
[   34.240967 01-05 13:30:49.477] pc : [<c01e332c>]    lr : [<c01e3304>]    psr: 200f0113
[   34.240972 01-05 13:30:49.477] sp : e0e9fe38  ip : 0000000a  fp : e0e9fe9c
[   34.255914 01-05 13:30:49.492] r10: 00000021  r9 : e09382c0  r8 : e092f908
[   34.262824 01-05 13:30:49.499] r7 : 00000000  r6 : 00008180  r5 : 00040d7b  r4 : e0e79800
[   34.271078 01-05 13:30:49.507] r3 : 00000000  r2 : 00000000  r1 : 0000000a  r0 : 0000000a
[   34.279334 01-05 13:30:49.516] Flags: nzCv  IRQs on  FIQs on  Mode SVC_32  ISA ARM  Segment user
[   34.288153 01-05 13:30:49.524] Control: 10c5387d  Table: a6f9c04a  DAC: 00000015
...
[   34.943888 01-05 13:30:50.180] Process system_server (pid: 928, stack limit = 0xe0e9e2f0)
[   34.952098 01-05 13:30:50.188] Stack: (0xe0e9fe38 to 0xe0ea0000)
...
[   35.096737 01-05 13:30:50.333] ffe0: 57769af4 be905398 4005c331 40067b78 200f0110 60832fa0 f0000a17 a8c00000
[   35.106647 01-05 13:30:50.343] [<c01e332c>] (ext4_free_inode+0x288/0x574) from [<c01ec5e0>] (ext4_evict_inode+0x2f0/0x4c0)
[   35.117770 01-05 13:30:50.354] [<c01ec5e0>] (ext4_evict_inode+0x2f0/0x4c0) from [<c0170da4>] (evict+0x9c/0x184)
[   35.127937 01-05 13:30:50.364] [<c0170da4>] (evict+0x9c/0x184) from [<c0171328>] (iput+0x104/0x1ec)
[   35.137061 01-05 13:30:50.373] [<c0171328>] (iput+0x104/0x1ec) from [<c01658ac>] (do_unlinkat+0x11c/0x160)
[   35.146793 01-05 13:30:50.383] [<c01658ac>] (do_unlinkat+0x11c/0x160) from [<c016731c>] (sys_unlink+0x20/0x24)
[   35.156873 01-05 13:30:50.393] [<c016731c>] (sys_unlink+0x20/0x24) from [<c000f040>] (ret_fast_syscall+0x0/0x30)

T32로 아래 명령어를 쓰면 어드레스가 소스 어느 라인인 지 알 수 있다.
y.l.line 0xc01e332c
___address___to_______________|source\line_____________________________________________________________________________________________________________________________|offset____|
     P:0000:C01E32F0--C01E32F7|\\vmlinux\unwind\/home001/seunghwan.moon/project/build/LAPAP40IKR140103/android/kernel/include/linux/spinlock.h\275--285                |      n.f.
     P:0000:C01E32F8--C01E3303|\\vmlinux\ext4/ialloc\/android/kernel/fs/ext4/ialloc.c\249--249                   |      n.f.
     P:0000:C01E3304--C01E330B|\\vmlinux\android/kernel/include/asm-generic/bitops/non-atomic.h\79--79|      n.f.
     P:0000:C01E330C--C01E330F|\\vmlinux\/android/kernel/include/asm-generic/bitops/non-atomic.h\65--78|      n.f.
     P:0000:C01E3310--C01E3313|\\vmlinux\/android/kernel/include/asm-generic/bitops/non-atomic.h\79--79|      n.f.
     P:0000:C01E3314--C01E3317|\\vmlinux\android/kernel/include/asm-generic/bitops/non-atomic.h\65--78|      n.f.
     P:0000:C01E3318--C01E331F|\\vmlinux\android/kernel/include/asm-generic/bitops/non-atomic.h\79--79|      n.f.
     P:0000:C01E3320--C01E332B|\\vmlinux\android/kernel/include/asm-generic/bitops/non-atomic.h\65--78|      n.f.
_____P:0000:C01E332C--C01E332F|\\vmlinux\android/kernel/include/asm-generic/bitops/non-atomic.h\80--80|______n.f.
     P:0000:C01E3330--C01E3337|\\vmlinux\android/kernel/include/asm-generic/bitops/non-atomic.h\65--78|      n.f.
     P:0000:C01E3338--C01E333B|\\vmlinux\android/kernel/include/asm-generic/bitops/non-atomic.h\83--83|      n.f.
     P:0000:C01E333C--C01E3343|\\vmlinux\android/kernel/include/asm-generic/bitops/non-atomic.h\81--82|      n.f.

소스를 따라가 보면, 266 라인에서 패닉이 발생했다는 것을 알 수 있다.
[kernel/fs/ext4/ialloc.c]
 193 void ext4_free_inode(handle_t *handle, struct inode *inode)
 194 {
 195     struct super_block *sb = inode->i_sb;
 196     int is_directory;
...
 259     fatal = -ESRCH;
 260     gdp = ext4_get_group_desc(sb, block_group, &bh2);
 261     if (gdp) {
 262         BUFFER_TRACE(bh2, "get_write_access");
 263         fatal = ext4_journal_get_write_access(handle, bh2);
 264     }
 265     ext4_lock_group(sb, block_group);
 266     cleared = ext4_test_and_clear_bit(bit, bitmap_bh->b_data);
 267     if (fatal || !cleared) {
 268         ext4_unlock_group(sb, block_group);
 269         goto out;
 270     }

ext4_test_and_clear_bit() 함수에 전달되는 파라미터 bit, bitmap_bh->b_data를 분석해보자.
확인해보면 아래와 같다.
  (register long unsigned int) bit_=_10_=_0x0A_=_'....'
  (register struct buffer_head *) bitmap_bh = 0xE092F908 = __bss_stop+0x1FA78EE8 -> (
    (long unsigned int) b_state = 8667177 = 0x00844029 = '..@)',
    (struct buffer_head *) b_this_page = 0xE092F908 = __bss_stop+0x1FA78EE8 -> ((long unsigned int) b_state = 8667177 = 0x00844029 = '..@
    (struct page *) b_page = 0xC172DF14 = __bss_stop+0x8774F4 -> ((long unsigned int) flags = 1073743972 = 0x40000864 = '@..d', (struct a
    (sector_t) b_blocknr = 1081345 = 0x00108001,
    (size_t) b_size = 4096 = 0x1000 = '....',
    (char *) b_data = 0x0 =  -> NULL,
    (struct block_device *) b_bdev = 0xE08FFC80 = __bss_stop+0x1FA49260 -> ((dev_t) bd_dev = 271581186 = 0x10300002 = '.0..', (int) bd_op

bitmap_bh->b_data 이넘이 NULL이네. 그래서 패닉이 발생한 것이다. 그럼 왜 이놈이 NULL인지 알아보자.
gdp란 변수가 NULL이 아니므로 ext4_journal_get_write_access() 함수가 호출이 되었다.
    fatal = -ESRCH;
    gdp = ext4_get_group_desc(sb, block_group, &bh2);
    if (gdp) {
        BUFFER_TRACE(bh2, "get_write_access");
        fatal = ext4_journal_get_write_access(handle, bh2);
    }
    ext4_lock_group(sb, block_group);
    cleared = ext4_test_and_clear_bit(bit, bitmap_bh->b_data);
    if (fatal || !cleared) {


struct buffer_head, struct에 대해서 확인을 해보면 아래와 같다.
bh->b_data은 아래와 같이 ext4_init_block_bitmap()함수에서 초기화한다.
/* Initializes an uninitialized block bitmap */
void ext4_init_block_bitmap(struct super_block *sb, struct buffer_head *bh,
                ext4_group_t block_group,
                struct ext4_group_desc *gdp)
{
...
    /* If checksum is bad mark all blocks used to prevent allocation
     * essentially implementing a per-group read-only flag. */
    if (!ext4_group_desc_csum_verify(sbi, block_group, gdp)) {
        ext4_error(sb, "Checksum bad for group %u", block_group);
        ext4_free_group_clusters_set(sb, gdp, 0);
        ext4_free_inodes_set(sb, gdp, 0);
        ext4_itable_unused_set(sb, gdp, 0);
        memset(bh->b_data, 0xff, sb->s_blocksize);
        return;
    }
    memset(bh->b_data, 0, sb->s_blocksize);

    bit_max = ext4_num_base_meta_clusters(sb, block_group);
}

Linux에서 대부분의 입출력은 파일을 통해서 이루어지고 그럴 경우 페이지 크기인 4KB 단위로 이루어진다. 파일시스템 수퍼블락을 하드디스크로 쓸 경우 struct buffer_head 구조체를 이용하여 1KB 씩 디스크에 입출력을 한다. 파일 데이터는 디스크 상의 특정 블록에 존재하며 이들 간의 매핑 정보를 유지하고 있는 것이 바로 buffer_head이다.

즉 디스크가 깨진 것이다.

그럼 system_server 프로세스 이전에 어떤 프로세스가 호출이 되었는 지 한번 살펴보자.
이 때 크래시를 써보자. 태스트 디스크립터(TCB)에 last_arrival란 변수가 있는 데 이 변수로 프로세스가 처리된 순서를 알 수 있다.
crash> foreach task | grep last_arrival

mmcqd/0란 태스크의 콜 스택이 깨져있네?
35181519000  workqueue_trust
__schedule) from [<c082b47c>]
schedule) from [<c082932c>]
schedule_timeout) from [<c082a7c0>]
wait_for_common) from [<c082a884>]
wait_for_completion) from [<c0098da0>]
kthread_stop) from [<c0090b78>]
destroy_worker) from [<c0821814>]
trustee_thread) from [<c0098d2c>]
kthread) from [<c000fca4>]

35181472000    wpa_supplicant
"__schedule) from [<c082b47c>]                                 
schedule) from [<c082b764>]                                   
schedule_preempt_disabled) from [<c0829f1c>]                  
__mutex_lock_slowpath) from [<c082a000>]                      
mutex_lock) from [<c0044b70>]                                 
tttt_dvfs_set_rate) from [<c0029b5c>]                        
clk_enable_locked) from [<c0029c64>]                          
clk_enable) from [<c058c6f0>]                                 
tttt_sdhci_set_clock) from [<c05887d8>]                      
sdhci_enable) from [<c056e0ec>]                               
__mmc_claim_host) from [<c0578098>]                           
sdio_reset_comm) from [<bf024b94>]                            
sdioh_start [bcmdhd]) from [<bf026fa8>]                       
wl_android_wifi_on [bcmdhd]) from [<bf0071f8>]                
dhd_open [bcmdhd]) from [<c066108c>]                          
__dev_open) from [<c06612f8>]                                 
__dev_change_flags) from [<c0661444>]                         
dev_change_flags) from [<c06e5a98>]                           
devinet_ioctl) from [<c06e6720>]                              
inet_ioctl) from [<c0649694>]                                 
sock_ioctl) from [<c016908c>]                                 
do_vfs_ioctl) from [<c016965c>]                               
sys_ioctl) from [<c000f040>]                                  
                        
"
35181467000    kworker/2:1    "__schedule) from [<c082b47c>]
schedule) from [<c0093e50>]
worker_thread) from [<c0098d2c>]
kthread) from [<c000fca4>]"

35181376000    mmcqd/0   
(__schedule) from [<df79aa80>]

35179614000    AudioOut_2    "__schedule) from [<c082b47c>]
schedule) from [<c082a0bc>]
do_nanosleep) from [<c009e5e8>]
hrtimer_nanosleep) from [<c009e710>]
sys_nanosleep) from [<c000f040>]"