川井拓真

Linuxカーネルにおけるメモリ破壊の不具合解析

Linuxカーネルに限らず、メモリ破壊による不具合の解析は一般に難しいものです。 最終的に観測されるシステムクラッシュなどの事象と、その原因となるメモリ破壊は非同期的に起きていることが多く、真因特定にはしばしば多大なコストを要します。

本稿では、Linuxカーネル空間でのメモリ破壊が疑われる事例における解析テクニックを紹介します。

例

以下のカーネルモジュールを例に解析の手続きを説明します。

#include <linux/init.h>
#include <linux/string.h>
#include <linux/slab.h>
#include <linux/debugfs.h>

struct test_data {
        char name[16];
        spinlock_t lock;
};

static int crash_test_get(void *data, u64 *val)
{
        struct test_data *test_data = data;
        unsigned long flags;

        (void)val;

        spin_lock_irqsave(&test_data->lock, flags);
        pr_err("%s: %s\n", __func__, test_data->name);
        // do something
        spin_unlock_irqrestore(&test_data->lock, flags);

        return 0;
}

DEFINE_DEBUGFS_ATTRIBUTE(crash_test_fops, crash_test_get, NULL, "%llu\n");

static int __init test_init(void)
{
        static struct test_data *test_data;

        test_data = kzalloc(sizeof(*test_data), GFP_KERNEL);
        spin_lock_init(&test_data->lock);

        // buffer overflow
        // this cannot be detected by KASAN
        strcpy(test_data->name, "deadbeef0123456789abcdef");

        debugfs_create_file("crash_test", 0666, NULL, test_data, &crash_test_fops);
        return 0;
}

postcore_initcall(test_init);

このモジュールをImageにリンクしておくと、以下のコマンドでOopsを引き起こします。 通常の.configでは単にcatコマンドがクラッシュするだけですが、以下の例ではCONFIG_PANIC_ON_OOPS=yとしてパニックを起こしています。

# mount -t debugfs none /sys/kernel/debug
# cat /sys/kernel/debug/crash_test
[   17.518873] Unable to handle kernel paging request at virtual address ffffffd662746690
[   17.519279] Mem abort info:
[   17.519383]   ESR = 0x96000045
[   17.519528]   EC = 0x25: DABT (current EL), IL = 32 bits
[   17.519832]   SET = 0, FnV = 0
[   17.519987]   EA = 0, S1PTW = 0
[   17.520138]   FSC = 0x05: level 1 translation fault
[   17.520347] Data abort info:
[   17.520471]   ISV = 0, ISS = 0x00000045
[   17.520631]   CM = 0, WnR = 1
[   17.520807] swapper pgtable: 4k pages, 39-bit VAs, pgdp=00000000406c8000
[   17.521049] [ffffffd662746690] pgd=0000000000000000, p4d=0000000000000000, pud=0000000000000000
[   17.521605] Internal error: Oops: 96000045 [#1] SMP
[   17.522006] CPU: 1 PID: 81 Comm: cat Not tainted 5.18.14+ #16
[   17.522302] Hardware name: linux,dummy-virt (DT)
[   17.522660] pstate: 800000c5 (Nzcv daIF -PAN -UAO -TCO -DIT -SSBS BTYPE=--)
[   17.522953] pc : queued_spin_lock_slowpath+0x1e8/0x2d0
[   17.523250] lr : crash_test_get+0x48/0xb0
[   17.523450] sp : ffffff80015ffcd0
[   17.523591] x29: ffffff80015ffcd0 x28: ffffff8000eb4980 x27: 0000000000000000
[   17.524030] x26: 0000000000000000 x25: 0000000000000000 x24: 0000000000001000
[   17.524317] x23: 0000007fd1df2e78 x22: ffffff800168bed0 x21: 0000000000000000
[   17.524600] x20: 0000000000000000 x19: ffffff8000dc1500 x18: 0000000000000000
[   17.524869] x17: 0000000000000000 x16: 0000000000000000 x15: 0000000000000000
[   17.525182] x14: 0000000000000000 x13: 0000000000000000 x12: 0000000000000000
[   17.525463] x11: 0000000000000000 x10: 0000000000000000 x9 : ffffffeb31425ec0
[   17.525777] x8 : ffffffeb313207d0 x7 : 0000000000000000 x6 : ffffff803fdd47c0
[   17.526074] x5 : 0000000000080000 x4 : ffffffeb313207d0 x3 : ffffff803fdd47c0
[   17.526406] x2 : ffffffeb313207c0 x1 : ffffff803fdd47c8 x0 : ffffff8000dc1510
[   17.526869] Call trace:
[   17.527058]  queued_spin_lock_slowpath+0x1e8/0x2d0
[   17.527388]  simple_attr_read+0x58/0xf0
[   17.527574]  debugfs_attr_read+0x48/0x90
[   17.527803]  full_proxy_read+0x5c/0xb0
[   17.527968]  vfs_read+0x6c/0xe4
[   17.528123]  ksys_read+0x54/0xd0
[   17.528273]  __arm64_sys_read+0x18/0x20
[   17.528451]  invoke_syscall.constprop.0+0x58/0x100
[   17.528659]  do_el0_svc+0x48/0xe0
[   17.528820]  el0_svc+0x14/0x50
[   17.528967]  el0t_64_sync_handler+0x9c/0x120
[   17.529155]  el0t_64_sync+0x148/0x14c
[   17.529497] Code: 910020c1 8b080048 f864d929 aa0803e4 (f8296886)
[   17.530158] ---[ end trace 0000000000000000 ]---
[   17.530531] Kernel panic - not syncing: Oops: Fatal exception
[   17.530860] SMP: stopping secondary CPUs
[   17.531260] Kernel Offset: 0x2b28e00000 from 0xffffffc008000000
[   17.531479] PHYS_OFFSET: 0x40000000
[   17.531618] CPU features: 0x000,00004000,00001002
[   17.531977] Memory Limit: none
[   17.532262] ---[ end Kernel panic - not syncing: Oops: Fatal exception ]---

基本戦略

メモリ破壊の難しさは、破壊が起きてから実際にシステムクラッシュなどの現象が観測されるまでにタイムラグがあることに由来しています。 真因の特定に至るための方針として、デバッグ機能を活用して異常をより早く検出することを目指します。

マジックナンバー系オプション

上記のサンプルコードでは意図的にバッファオーバーフローを起こしていますが、ここでは現段階ではまだ真因を特定していないつもりで考えます。

パニック発生時のログを見たところ、queued_spin_lock_slowpathでアドレスffffffd662746690に対する不正メモリアクセスが起きていることから、spin_lock_irqsaveの第一引数に不正なアドレスを渡してしまったか、spinlock_t lockの内容が破壊されてしまった可能性が考えられます。まずはこのことを確かめます。

Linuxカーネルにはメモリ破壊等を早めに検知するため構造体にマジックナンバーを入れ、API実行時にこれを確認する機能があります。 今回はスピンロックを確認したいのでCONFIG_DEBUG_SPINLOCK=yとしてみます。

マジックナンバーが壊れているので、以下のようなBUGが出ます。

[   10.152992] BUG: spinlock bad magic on CPU#0, cat/82
[   10.153311]  lock: 0xffffff8000d47790, .magic: 66656463, .owner: <none>/-1, .owner_cpu: -256
[   10.154032] CPU: 0 PID: 82 Comm: cat Kdump: loaded Not tainted 5.18.14+ #17
[   10.154412] Hardware name: linux,dummy-virt (DT)
[   10.154788] Call trace:
[   10.154981]  dump_backtrace.part.0+0xb4/0xc0
[   10.155341]  show_stack+0x14/0x20
[   10.155563]  dump_stack_lvl+0x78/0x98
[   10.155727]  dump_stack+0x14/0x2c
[   10.155883]  spin_dump+0x84/0x90
[   10.156036]  do_raw_spin_lock+0xb4/0x100
[   10.156214]  _raw_spin_lock_irqsave+0x4c/0x60
[   10.156405]  crash_test_get+0x1c/0x60
[   10.156612]  simple_attr_read+0x58/0xf0
[   10.156782]  debugfs_attr_read+0x48/0x90
[   10.156966]  full_proxy_read+0x5c/0xb0
[   10.157139]  vfs_read+0x6c/0xe4
[   10.157289]  ksys_read+0x54/0xd0
[   10.157441]  __arm64_sys_read+0x18/0x20
[   10.157619]  invoke_syscall.constprop.0+0x58/0x100
[   10.157824]  do_el0_svc+0x48/0xe0
[   10.157980]  el0_svc+0x14/0x50
[   10.158126]  el0t_64_sync_handler+0x9c/0x120
[   10.158310]  el0t_64_sync+0x148/0x14c

spin_lock_irqsaveに渡しているポインタ0xffffff8000d47790はカーネル空間のアドレスとして典型的なもので、この段階でおそらくポインタは正しく、その内容が壊れているのだろうと当たりをつけます。

マジックナンバーが壊れているため、誤ったマジックナンバー66656463が表示されています。 今回はASCII文字列で破壊しているため、わかりやすいバイト列になっています。 この4バイトからデータ破壊を起こしている場所を特定できることもあります。

>>> bytes.fromhex('66656463')
b'fedc'

KASAN

ほとんどのメモリ破壊はKASANで特定できます。 CONFIG_KASAN=yとするだけで簡単に使用でき、kmallocの範囲外アクセスなど、不正アクセスが発生したタイミングで検出できます。

今回の例は構造体のフィールドからはみ出しているだけで、kmallocで取得した範囲外に書き込んでいるわけではないので、KASANでは検知できませんが、破壊の範囲がもっと広い場合は、以下のようにtest_initで破壊が起きたタイミングでの異常検知が可能です。

[    0.210723] ==================================================================
[    0.211358] BUG: KASAN: slab-out-of-bounds in test_init+0x7c/0xa4
[    0.211814] Write of size 44 at addr ffffff8001256f00 by task swapper/0/1
[    0.212162]
[    0.212538] CPU: 0 PID: 1 Comm: swapper/0 Not tainted 5.18.14+ #19
[    0.212940] Hardware name: linux,dummy-virt (DT)
[    0.213465] Call trace:
[    0.213634]  dump_backtrace.part.0+0x188/0x194
[    0.213961]  show_stack+0x14/0x20
[    0.214193]  dump_stack_lvl+0x80/0xa0
[    0.214447]  print_report+0x158/0x5a4
[    0.214722]  kasan_report+0xc8/0xec
[    0.214963]  kasan_check_range+0xf4/0x1a0
[    0.215230]  memcpy+0xdc/0x100
[    0.215450]  test_init+0x7c/0xa4
[    0.215653]  do_one_initcall+0xbc/0x1bc
[    0.215904]  kernel_init_freeable+0x228/0x288
[    0.216145]  kernel_init+0x24/0x140
[    0.216376]  ret_from_fork+0x10/0x20
[    0.216753]
[    0.216962] Allocated by task 1:
[    0.217259]  kasan_save_stack+0x28/0x50
[    0.217544]  __kasan_kmalloc+0x8c/0xb0
[    0.217848]  test_init+0x44/0xa4
[    0.218059]  do_one_initcall+0xbc/0x1bc
[    0.218286]  kernel_init_freeable+0x228/0x288
[    0.218527]  kernel_init+0x24/0x140
[    0.218737]  ret_from_fork+0x10/0x20
[    0.218993]
[    0.219156] The buggy address belongs to the object at ffffff8001256f00
[    0.219156]  which belongs to the cache kmalloc-128 of size 128
[    0.219704] The buggy address is located 0 bytes inside of
[    0.219704]  128-byte region [ffffff8001256f00, ffffff8001256f80)
[    0.220155]
[    0.220334] The buggy address belongs to the physical page:
[    0.220763] page:(____ptrval____) refcount:1 mapcount:0 mapping:0000000000000000 index:0x0 pfn:0x41256
[    0.221422] flags: 0x200(slab|zone=0)
[    0.222151] raw: 0000000000000200 0000000000000000 dead000000000122 ffffff8001002300
[    0.222535] raw: 0000000000000000 0000000080100010 00000001ffffffff 0000000000000000
[    0.222914] page dumped because: kasan: bad access detected
[    0.223183]
[    0.223312] Memory state around the buggy address:
[    0.223767]  ffffff8001256e00: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fc fc
[    0.224141]  ffffff8001256e80: fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc
[    0.224506] >ffffff8001256f00: 00 00 00 00 00 fc fc fc fc fc fc fc fc fc fc fc
[    0.224853]                                   ^
[    0.225143]  ffffff8001256f80: fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc
[    0.225475]  ffffff8001257000: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[    0.225823] ==================================================================

kdump

今回の例ではKASANで原因を特定できなかったため、kdumpを試してみることにします。 kdumpは、カーネルパニック発生時にkexecでレスキュー用のカーネルを起動し、クラッシュしたカーネルのcore dumpを取得する機能です。 これによりカーネルパニック発生時の状態を保存でき、gdbのようなインターフェースでデバッグできるようになります。

今回は発生現象からspinlock_tが破壊されたと当たりをつけているので、周辺がどのように壊れているか観察し、原因特定を試みます。

以下のコンフィグレーションを有効にしてカーネルを再ビルドし、vmlinuxをrootfsに入れておきます。

CONFIG_KEXEC=y
CONFIG_CRASH_DUMP=y
CONFIG_PROC_KCORE=y
CONFIG_PROC_VMCORE=y

kexec -pとしてパニック発生時に実行するvmlinuxをロードしてパニックを発生させると、新しいvmlinuxが起動し、/proc/vmcoreからクラッシュしたカーネルのcore dumpが得られます。

# kexec -p vmlinux --command-line='root=... nr_cpus=1 reset_devices'
# mount -t debugfs none /sys/kernel/debug
# cat /sys/kernel/debug/crash_test
[    8.775382] BUG: spinlock bad magic on CPU#1, cat/82
[    8.776003]  lock: 0xffffff8000d47790, .magic: 66656463, .owner: <none>/-1, .owner_cpu: -256
[    8.776750] CPU: 1 PID: 82 Comm: cat Kdump: loaded Not tainted 5.18.14+ #24
[    8.777002] Hardware name: linux,dummy-virt (DT)
...
[    8.797294] Code: 910020c1 8b080048 f864d929 aa0803e4 (f8296886)
[    8.798045] SMP: stopping secondary CPUs
[    8.799201] Starting crashdump kernel...
[    8.799732] Bye!
[    0.000000] Booting Linux on physical CPU 0x0000000001 [0x410fd034]
[    0.000000] Linux version 5.18.14+ (kawai@ubuntu22) (aarch64-linux-gnu-gcc (Ubuntu 11.2.0-17ubuntu1) 11.2.0, GNU ld (GNU Binutils for Ubuntu) 2.38) #23 SMP Tue Aug 2 04:23:11 UTC 2022
...
# cp /proc/vmcore .

vmlinuxとvmcoreをあわせると、カーネルパニック発生時のさまざまな情報が得られますが、今回は0xffffff8000d47790周辺のメモリダンプを見てみます。

まずvmcoreの解析ツールcrashをビルドします。

git clone https://github.com/crash-utility/crash
cd crash
make target=ARM64

crashツールでメモリダンプを表示し、破壊されている箇所にどのようなデータが書き込まれているか確認します。 今回の場合、deadbeef0123...という特徴的なASCII文字列で上書きされてしまっていることがわかるため、この情報から破壊が起きた場所を探します。

$ ~/crash/crash vmlinux vmcore
crash> rd 0xffffff8000d47700 -e 0xffffff8000d47800
ffffff8000d47700:  ffffff8000c47808 ffffff8000c47808   .x.......x......
ffffff8000d47710:  dead4ead00000000 00000000ffffffff   .....N..........
ffffff8000d47720:  ffffffffffffffff ffffffd6d647cc60   ........`.G.....
ffffff8000d47730:  ffffff8000d47730 ffffff8000d47730   0w......0w......
ffffff8000d47740:  ffffff8000d07028 0000000000000000   (p..............
ffffff8000d47750:  ffffffd6d65d9d58 ffffff8000da3180   X.]......1......
ffffff8000d47760:  0000000300000003 0000000000000000   ................
ffffff8000d47770:  0000000000000000 0000000000000000   ................
ffffff8000d47780:  6665656264616564 3736353433323130   deadbeef01234567
ffffff8000d47790:  6665646300083938 00000000ffffff00   89..cdef........
ffffff8000d477a0:  ffffffffffffffff 0000000000000000   ................
ffffff8000d477b0:  0000000000000000 0000000000000000   ................
ffffff8000d477c0:  0000000000000000 0000000000000000   ................
ffffff8000d477d0:  0000000000000000 0000000000000000   ................
ffffff8000d477e0:  0000000000000000 0000000000000000   ................
ffffff8000d477f0:  0000000000000000 0000000000000000   ................

まとめ

  • Linuxカーネルのメモリ操作に関するバグについて、本稿では以下のデバッグ機能を紹介しました

参考文献

付録: kdumpの手順

カーネル

git clone https://kernel.googlesource.com/pub/scm/linux/kernel/git/stable/linux.git -b linux-5.18.y linux-5.18.y
cd linux-5.18.y
git checkout v5.18.14
export CROSS_COMPILE=aarch64-linux-gnu-
export ARCH=arm64
make allnoconfig
make menuconfig
make -j8

コンフィグレーション

## for QEMU virt machine model
CONFIG_TTY=y
CONFIG_SERIAL_AMBA_PL011=y
CONFIG_SERIAL_AMBA_PL011_CONSOLE=y
CONFIG_NET=y
CONFIG_INET=y
CONFIG_PCI=y
CONFIG_PCI_HOST_GENERIC=y
CONFIG_VIRTIO_MENU=y
CONFIG_VIRTIO_PCI=y
CONFIG_NET_9P=y
CONFIG_9P_FS=y
CONFIG_9P_FS_POSIX_ACL=y
CONFIG_NET_9P_VIRTIO=y

## for busybox init
CONFIG_DEVTMPFS=y
CONFIG_DEVTMPFS_MOUNT=y
CONFIG_PROC_FS=y
CONFIG_SYSFS=y
CONFIG_BINFMT_ELF=y
CONFIG_BINFMT_SCRIPT=y
CONFIG_TMPFS=y
CONFIG_TMPFS_POSIX_ACL=y

## debug
CONFIG_PRINTK=y
CONFIG_PRINTK_TIME=y
CONFIG_STACKTRACE=y
CONFIG_BUG=y
CONFIG_DEBUG_INFO_DWARF5=y

## kexec
CONFIG_KALLSYMS=y
CONFIG_KALLSYMS_ALL=y
CONFIG_PM=y
CONFIG_SUSPEND=y
CONFIG_KEXEC=y
CONFIG_CRASH_DUMP=y
CONFIG_PROC_KCORE=y
CONFIG_PROC_VMCORE=y
CONFIG_RANDOMIZE_BASE=y

## demo driver
CONFIG_DEBUG_FS=y
CONFIG_PANIC_ON_OOPS=y

## make kernel panic
CONFIG_MAGIC_SYSRQ=y

Buildroot

git clone https://github.com/buildroot/buildroot.git -b 2022.05 buildroot-2022.05
cd buildroot-2022.05
make menuconfig
make -j8

コンフィグレーション

BR2_aarch64=y
BR2_TOOLCHAIN_EXTERNAL=y
BR2_TOOLCHAIN_EXTERNAL_ARM_AARCH64=y
BR2_PACKAGE_KEXEC=y

QEMU

$ qemu-system-aarch64 \
    -cpu cortex-a53 -m 1G -smp 2 \
    -M virt \
    -nographic \
    -append 'earlycon=pl011,0x09000000 root=fs0 rw rootfstype=9p rootflags=trans=virtio console=ttyAMA0 crashkernel=256M debug' \
    -serial mon:stdio \
    -kernel ~/linux-5.18.y/arch/arm64/boot/Image \
    -fsdev local,security_model=none,id=fsdev-root,multidevs=remap,path=$HOME/buildroot-2022.05/output/target/ \
    -device virtio-9p-pci,id=fs0,fsdev=fsdev-root,mount_tag=fs0
...
# kexec -p vmlinux --command-line='earlycon=pl011,0x09000000 root=fs0 rw rootfstype=9p rootflags=trans=virtio console=ttyAMA0 debug nr_cpus=1 reset_devices'
# echo c > /proc/sysrq-trigger

コメントを残す

メールアドレスが公開されることはありません。 ※ が付いている欄は必須項目です