#커널 크래시 디버깅 및 TroubleShooting
- Race로 mmc_wait_data_done() 함수에서 커널 패닉
- "cat /d/shrinker" 입력 시 커널 패닉
- 함수 포인터 미지정으로 xfrm_local_error() 커널 패닉
- preempt 조건으로 ___might_sleep() 함수 크래시
- 스택 카나리: __stack_chk_fail() 함수 크래시
- 스택 카나리: tcp_v4_rcv -> __stack_chk_fail 크래시
- 뮤텍스 데드락(Mutex Deadlock)으로 락업(lockup)
- 디바이스 드라이버 Signature 문제로 커널 크래시
- 메모리 불량 커널 크래시 @find_vma_links()
- 메모리 불량 커널 크래시 @ttwu_do_activate()
- Race로 ipv6_ifa_notify() Stuck - watchdog reset
- tty_wakeup() 함수 Data Abort
- irq_affinity_notify() 함수 Data Abort
- cpuacct_charge() 함수 Data Abort
- 워크큐(workqueue) 락업(1)
- 워크큐(workqueue) 락업(2)
- 워크큐(workqueue) 락업(3)
100% 커널 패닉으로 타겟이 죽어버리는 이슈를 발견했어요.
자자, 일단 커널 로그부터 좀 볼까요?
뭐, PID가 6978이 sh 프로세스에서 do_raw_spin_lock() 함수에서 데이터 어보트를 유발시켰네요.
[ 761.636711] Unable to handle kernel paging request at virtual address f38a9a84
[ 761.645048] pgd = e8074000
[ 761.649800] [f38a9a84] *pgd=a0721811, *pte=00000000, *ppte=00000000
[ 761.658106] Internal error: Oops: 7 [#1] PREEMPT SMP ARM
[ 761.665481] Modules linked in:
[ 761.670605] CPU: 6 PID: 6978 Comm: sh Tainted: G W 3.18.31-g5b0528e-dirty #12
[ 761.680852] task: eb5b8000 ti: d228e000 task.ti: d228e000
[ 761.688315] PC is at do_raw_spin_lock+0x8/0x17c
[ 761.694912] LR is at list_lru_count_node+0x14/0x60
//--- skip ---
[ 761.885719] [<c016a650>] (do_raw_spin_lock) from [<c02057f4>] (list_lru_count_node+0x14/0x60)
[ 761.896307] [<c02057f4>] (list_lru_count_node) from [<c022dffc>] (super_cache_count+0x40/0x94)
[ 761.906982] [<c022dffc>] (super_cache_count) from [<c01f2708>] (debug_shrinker_show+0x44/0x7c)
[ 761.917658] [<c01f2708>] (debug_shrinker_show) from [<c024a56c>] (seq_read+0x1a4/0x3f0)
[ 761.927726] [<c024a56c>] (seq_read) from [<c022c87c>] (vfs_read+0x88/0x138)
[ 761.936755] [<c022c87c>] (vfs_read) from [<c022cda8>] (SyS_read+0x3c/0x7c)
[ 761.945695] [<c022cda8>] (SyS_read) from [<c0106840>] (ret_fast_syscall+0x0/0x38)
[ 761.955242] Code: e12fff1e deaf1eed e92d47f0 e1a08000 (e5902004)
T32로 코어덤프를 올려서 콜스택을 잡아 봤어요.
do_raw_spin_lock() 함수 내에서 debug_spin_lock_before() 함수 호출을 하는데,
debug_spin_lock_before()는 spinlock 멤버 변수의 sanity-checkf를 하거든요. 그 동작에서 크래시가 난 거죠.
-000|do_DataAbort(addr = 170, fsr = 3247439880, regs = 0xEC4901C0)
-001|__dabt_svc(asm)
-->|exception
-002|debug_spin_lock_before(inline) //<<-- data abort
-002|do_raw_spin_lock(lock = 0xF38A9A80)
-003|list_lru_count_node(?, ?)
-004|super_cache_count(shrink = 0xEBC47DE0, sc = 0xD228FEF8)
-005|debug_shrinker_show(s = 0xE7CF63C0, ?)
-006|seq_read(file = 0xE805CA00, buf = 0xB3246000, size = 4096, ppos = 0xD228FF80)
-007|vfs_read(file = 0xFFFFFFFF, buf = 0x0, ?, pos = 0xD228FF80)
-008|SYSC_read(inline)
-008|sys_read(?, buf = -1289461760, count = 4096)
-009|ret_fast_syscall(asm)
스핀락 값을 좀 더 살펴봤더니, 역시나.
owner, next값이 왕창 깨져있네요. next는 owner보다 같거나(스핀락 해제), 1만큼만 크거든요.(스핀락 획득)
(register raw_spinlock_t *) [R0] lock = 0xF38A9A80 -> (
(arch_spinlock_t) [NSD:0xF38A9A80] raw_lock = (
(u32) [NSD:0xF38A9A80] slock = 0x6F632F34,
(struct __raw_tickets) [NSD:0xF38A9A80] tickets = (
(u16) [NSD:0xF38A9A80] owner = 0x2F34, //<<--
(u16) [NSD:0xF38A9A82] next = 0x6F63)), //<<--
(unsigned int) [NSD:0xF38A9A84] magic = 0x6E6F6D6D //<<--
(unsigned int) [NSD:0xF38A9A88] owner_cpu = 0x6F6F675F,
(void *) [NSD:0xF38A9A8C] owner = 0x5F656C67))
spin_lock 변수가 어디서 호출되었는지 살펴보면, &lru->node[nid]; 이네요.
list_lru_count_node() 함수의 첫 번째 파라미터로 넘어온 거죠.
51unsigned long
52list_lru_count_node(struct list_lru *lru, int nid)
53{
54 unsigned long count = 0;
55 struct list_lru_node *nlru = &lru->node[nid]; <<--
56
57 spin_lock(&nlru->lock);
The list_lru_count_node() 함수 출처를 살펴보면, super_cache_count() 함수 내 &sb->s_dentry_lru 로컬변수이네요.
08static unsigned long super_cache_count(struct shrinker *shrink,
109 struct shrink_control *sc)
110{
111 struct super_block *sb;
112 long total_objects = 0;
113
114 sb = container_of(shrink, struct super_block, s_shrink);
//snip
124 if (sb->s_op && sb->s_op->nr_cached_objects)
125 total_objects = sb->s_op->nr_cached_objects(sb,
126 sc->nid);
127
128 total_objects += list_lru_count_node(&sb->s_dentry_lru, //<<--
129 sc->nid);
이제 super_cache_count() 함수를 호출한 흐름을 따라가보면,
debug_shrinker_show() 함수 내 shrinker->count_objects(shrinker, &sc); 루틴임을 알 수 있어요.
205static int debug_shrinker_show(struct seq_file *s, void *unused)
206{
207 struct shrinker *shrinker;
208 struct shrink_control sc;
209
210 sc.gfp_mask = -1;
211 sc.nr_to_scan = 0;
212
213 down_read(&shrinker_rwsem);
214 list_for_each_entry(shrinker, &shrinker_list, list) {
215 int num_objs;
216
217 num_objs = shrinker->count_objects(shrinker, &sc); //<<-- shrinker->count_objects = super_cache_count
자자, 이제 좀 정리 좀 해볼까요?
함수에 따라 호출된 변수의 흐름을 살펴보죠.
1. super_cache_count() 함수에서 shrinker->count_objects(shrinker, &sc); 를 호출하죠.
2. list_lru_count_node(&sb->s_dentry_lru, sc->nid); // &sb->s_dentry_lru, sc->nid 변수를 파라미터로 넘기네요.
3. list_lru_count_node(struct list_lru *lru, int nid) // <<-- nid 파라미터 즉 sc->nid로 넘어온 값이 쓰레기 값이네요.
3.1 struct list_lru_node *nlru = &lru->node[nid]; // &lru->node[nid]; &lru->node[쓰레기값];
3.2 spin_lock(&nlru->lock); // &nlru->lock: 쓰레기 주소 접근
debug_shrinker_show() 함수에서 선언된 struct shrink_control sc 로컬 변수를 초기화하지 않고 Call-by-value로 호출하는게 문제였어요.
구글링을 해보니, 이미 구글에서 패치를 릴리즈했네요. 좀 미리 문제를 알았으면 오픈 소스에 Contribution할 수 있었는데 아쉽네요.
Commit log
ANDROID: Revert "mm: vmscan: Add a debug file for shrinkers"
Kernel panic when type "cat /sys/kernel/debug/shrinker"
Unable to handle kernel paging request at virtual address 0af37d40
pgd = d4dec000
[0af37d40] *pgd=00000000
Internal error: Oops: 5 [#1] PREEMPT SMP ARM
[<c0bb8f24>] (_raw_spin_lock) from [<c020aa08>] (list_lru_count_one+0x14/0x28)
[<c020aa08>] (list_lru_count_one) from [<c02309a8>] (super_cache_count+0x40/0xa0)
[<c02309a8>] (super_cache_count) from [<c01f6ab0>] (debug_shrinker_show+0x50/0x90)
[<c01f6ab0>] (debug_shrinker_show) from [<c024fa5c>] (seq_read+0x1ec/0x48c)
[<c024fa5c>] (seq_read) from [<c022e8f8>] (__vfs_read+0x20/0xd0)
[<c022e8f8>] (__vfs_read) from [<c022f0d0>] (vfs_read+0x7c/0x104)
[<c022f0d0>] (vfs_read) from [<c022f974>] (SyS_read+0x44/0x9c)
[<c022f974>] (SyS_read) from [<c0107580>] (ret_fast_syscall+0x0/0x3c)
Code: e1a04000 e3a00001 ebd66b39 f594f000 (e1943f9f)
---[ end trace 60c74014a63a9688 ]---
Kernel panic - not syncing: Fatal exception
shrink_control.nid is used but not initialzed, same for
shrink_control.memcg.
This reverts commit b0e7a582b2264cdf75874dcd8df915b6b4427755.
Reported-by: Xiaowen Liu <xiaowen.liu@freescale.com>
Signed-off-by: Dmitry Shmidt <dimitrysh@google.com>
# Reference: For more information on 'Linux Kernel';
디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 1
디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 2
'Core BSP 분석 > 커널 트러블슈팅' 카테고리의 다른 글
[Linux][Kernel]뮤텍스 데드락(Mutex Deadlock) 락업(lockup) - "simpleperf" 디버깅 (0) | 2023.05.07 |
---|---|
[Linux][Kernel] Kernel Panic @__stack_chk_fail - 스택 카나리 (Stack canary Feature) (0) | 2023.05.07 |
[Linux][Kernel] panic@___might_sleep (0) | 2023.05.07 |
[Linux][Kernel][Stability] Kernel panic @0x0 from xfrm_local_error+0x4c (0) | 2023.05.07 |
[Linux-Kernel][Debug]kernel panic@mmc_wait_data_done (0) | 2023.05.07 |