#커널 크래시 디버깅 및 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)
CPU: 3 PID: 435 Comm: kworker/u17:2 프로세스에서 dm-verity를 처리하는 워크 함수 verity_prefetch_io 서브 루틴에서 커널 데이터 어보트가 발생했습니다.
-000|do_DataAbort(addr = 0, fsr = 0, regs = 0x0)
-001|__dabt_svc(asm)
-->|exception
-002|ttwu_activate(inline)
-002|ttwu_do_activate.constprop.52(rq = 0xEB95AB80, p = 0xFFFFF69B)
-003|ttwu_queue(inline)
-003|try_to_wake_up(p = 0xEB95AB80, ?, wake_flags = -237815936)
-004|arch_spin_unlock(inline)
-004|__mutex_unlock_common_slowpath(inline)
-004|__mutex_unlock_slowpath(lock_count = 0xEB5BCB40)
-005|dm_bufio_prefetch(c = 0xEB5BCB40, block = 903261, ?)
-006|verity_prefetch_io(work = 0xF1D33780)
-007|static_key_count(inline)
-007|static_key_false(inline)
-007|trace_workqueue_execute_end(inline)
-007|process_one_work(worker = 0xEB063500, work = 0xD36AF980)
-008|worker_thread(__worker = 0xF1D33780)
-009|kthread(_create = 0xEB06EEC0)
-010|ret_from_fork(asm)
-011|ret_fast_syscall(asm)
dm_bufio_prefetch 코드에서 mutex_unlock하는 동작 중 struct mutex.wait_list에 등록된 프로세스를 깨우는 동작이었습니다.
해당 mutex는 아래 변수이며, struct mutex.wait_list에 가장 먼저 등록한 struct mutex.wait_list.next 프로세스를 깨웁니다.
(struct mutex *) (struct mutex*)0xEB5BCB40 = 0xEB5BCB40 = __key+0x295D6EA4 -> (
(atomic_t) count = ((int) counter = 1 = 0x1 = '....'),
(spinlock_t) wait_lock = ((struct raw_spinlock) rlock = ((arch_spinlock_t) raw_lock = ((u32) slo
(struct list_head) wait_list = (
(struct list_head *) next = 0xE9F91D78 //<<--
(struct list_head *) next = 0xE90ADD78
(struct list_head *) next = 0xEAFFFE08
(struct list_head *) next = 0xE5FD5E18
(struct list_head *) next = 0xE90F7D78
struct mutex.wait_list.next 프로세스의 정체는 struct task_struct 가 0xEB95AB80 인 "kworker/u17:4" 프로세스입니다.
v.v %t %h %s container_of(0xE9F91D78,struct mutex,wait_list)
(struct mutex *) container_of(0xE9F91D78,struct mutex,wait_list) = 0xE9F91D64 -> (
(atomic_t) count = ((int) counter = 0xEB5BCB54),
(spinlock_t) wait_lock = ((struct raw_spinlock) rlock = ((arch_spinlock_t) raw_lock = ((u32) slo
(struct list_head) wait_list = ((struct list_head *) next = 0xE90ADD78, (struct list_head *) pre
(struct task_struct *) owner = 0xEB95AB80 -> ( //<<--
(long int) state = 0x0100,
(void *) stack = 0xE9F90000,
(atomic_t) usage = ((int) counter = 0x2),
// .. 생략 ..
(struct cred *) cred = 0xEB063C00,
(char [16]) comm = "kworker/u17:4",
"kworker/u17:4" 프로세스의 콜스택을 보면 역시 뮤텍스락을 얻기 위해 휴면에 진입한 상태였습니다.
v.f /task 0xEB95AB80
-000|context_switch(inline)
-000|__schedule()
-001|schedule_preempt_disabled()
-002|__mutex_lock_common(inline)
-002|__mutex_lock_slowpath(lock_count = 0xEB5BCB40)
-003|current_thread_info(inline)
-003|mutex_set_owner(inline)
-003|mutex_lock(lock = 0xEB5BCB40)
-004|new_read(c = 0xEB5BCB40, block = 903235, nf = NF_READ, bp = 0xE9F91E1C)
-005|dm_bufio_read(?, ?, ?)
-006|verity_verify_level(v = 0xEB140400, io = 0xE9ED5A00, ?, ?, skip_unverified = FALSE, want_digest = 0x
-007|verity_hash_for_block(v = 0xEB140400, io = 0xE9ED5A00, block = 847125, digest = 0xE9ED5B10, is_zero
-008|verity_verify_io(inline)
-008|verity_work(w = 0x0)
-009|static_key_count(inline)
-009|static_key_false(inline)
-009|trace_workqueue_execute_end(inline)
-009|process_one_work(worker = 0xEB1F2A80, work = 0xE9ED5A38)
-010|worker_thread(__worker = 0x0)
-011|kthread(_create = 0xEB7D7E00)
-012|ret_from_fork(asm)
-013|ret_fast_syscall(asm)
다음 5줄 어셈블리 코드에서 데이터 어보트가 발생했는데, 이유는 R4가 0xFFFFF69B란 값을 담고 있었기 때문입니다.
MMU가 0xFFFFF69B란 가상 메모리를 처리하지 못해 ARM이 데이터 어보트를 유발한 것입니다.
1______addr/line|code_____|label____|mnemonic________________|comment
2 NSR:C014E914|158034D0 strne r3,[r0,#0x4D0]
3 NSR:C014E918|EBFFFECB bl 0xC014E44C ; activate_task
4 NSR:C014E91C|E3A03001 mov r3,#0x1 ; r3,#1
5___NSR:C014E920|E584302C____________str_____r3,[r4,#0x2C]
그럼 "str_____r3,r4,#0x2C" 이 어셈블리 코드의 정체는 뭘까요? struct task_struct 자료구조에서 on_rq에 멤버에 접근하는 코드입니다.
(int) offsetof(struct task_struct,on_rq) = 44 = 0x2C = '...,'
이렇게 암흑의 어셈블리 코드 세상에서 벗어나 C 코드로 이동해보면 아래 4785 줄 에서 데이터 어보트가 발생했음을 알 수 있습니다.
4782static inline void ttwu_activate(struct rq *rq, struct task_struct *p, int en_flags)
4783{
4784 activate_task(rq, p, en_flags);
4785 p->on_rq = TASK_ON_RQ_QUEUED;
4786
4787 /* if a worker is waking up, notify workqueue */
4788 if (p->flags & PF_WQ_WORKER)
4789 wq_worker_waking_up(p, cpu_of(rq));
4790}
ttwu_activate 함수를 눈 여겨 보면 두 번째 파라미터가 struct task_struct *p이고 이 파라미터가 0xFFFFF69B란 주소를 담고 있는게 문제입니다.
다음 5줄 어셈블리 코드에서 데이터 어보트가 발생했는데, 이유는 R4가 0xFFFFF69B란 값을 담고 있었기 때문입니다.
MMU가 0xFFFFF69B란 가상 메모리를 처리하지 못해 ARM이 데이터 어보트를 유발한 것입니다.
1______addr/line|code_____|label____|mnemonic________________|comment
2 NSR:C014E914|158034D0 strne r3,[r0,#0x4D0]
3 NSR:C014E918|EBFFFECB bl 0xC014E44C ; activate_task
4 NSR:C014E91C|E3A03001 mov r3,#0x1 ; r3,#1
5___NSR:C014E920|E584302C____________str_____r3,[r4,#0x2C]
그럼 ttwu_activate 함수는 어느 함수가 호출했을까요?
코드를 조금 살펴보면 아래 4981줄에서 호출했음을 알 수 있습니다.
두번 째 파라미터로 전달하고 있으니 어셈블리 코드로 보면 R1으로 전달하겠죠.
4968static void ttwu_queue(struct task_struct *p, int cpu)
4969{
4970 struct rq *rq = cpu_rq(cpu);
4971
4972#if defined(CONFIG_SMP)
4973 if (sched_feat(TTWU_QUEUE) && !cpus_share_cache(smp_processor_id(), cpu)) {
4974 sched_clock_cpu(cpu); /* sync clocks x-cpu */
4975 ttwu_queue_remote(p, cpu);
4976 return;
4977 }
4978#endif
4979
4980 raw_spin_lock(&rq->lock);
4981 ttwu_do_activate(rq, p, 0); //<<--
4982 raw_spin_unlock(&rq->lock);
4983}
예상했다 싶히, R10에서 R1으로 struct task_struct *p 값을 전달하네요.
그럼 Trace32 프로그램에서는 R10이 0xEB95AB80 주소를 담고 있습니다.
1 NSR:C015597C|E1A00008 cpy r0,r8
2 NSR:C0155980|EB3ADE16 bl 0xC100D1E0 ; _raw_spin_lock
3 NSR:C0155984|E1A00008 cpy r0,r8
4 NSR:C0155988|E1A0100A cpy r1,r10 ; r1,p
5 NSR:C015598C|EBFFE3D7 bl 0xC014E8F0 ; ttwu_do_activate.constprop.52
0xEB95AB80 주소를 struct task_struct 구조체로 캐스팅해볼까요?
아래 명령어로 확인해보니 정말 태스크 디스크립터는 정상 멤버 값들을 담고 있군요.
(struct task_struct*)0xEB95AB80 = 0xEB95AB80 -> (
state = 256 = 0x0100,
stack = 0xE9F90000,
usage = (counter = 2 = 0x2),
flags = 69238880 = 0x04208060,
// .. 생략..
real_cred = 0xEB063C00,
cred = 0xEB063C00,
comm = "kworker/u17:4",
link_count = 0 = 0x0,
아까 뮤텍스락 디버깅을 했었죠? 그 때 정보를 되살려 보면
0xEB95AB80 struct task_struct 구조체 주소는 뮤텍스락 wait_list.next에 등록된 프로세스의 태스크 디스크립터입니다.
v.v %t %h %s container_of(0xE9F91D78,struct mutex,wait_list)
(struct mutex *) container_of(0xE9F91D78,struct mutex,wait_list) = 0xE9F91D64 -> (
(atomic_t) count = ((int) counter = 0xEB5BCB54),
(spinlock_t) wait_lock = ((struct raw_spinlock) rlock = ((arch_spinlock_t) raw_lock = ((u32) slo
(struct list_head) wait_list = ((struct list_head *) next = 0xE90ADD78, (struct list_head *) pre
(struct task_struct *) owner = 0xEB95AB80 -> ( //<<--
(long int) state = 0x0100,
(void *) stack = 0xE9F90000,
다시 원래 했던 디버깅 흐름으로 돌아와서.
그럼 두 번째 파라미터 전달했던 struct task_struct *p에 해당하는 0xEB95AB80 주소가 0xFFFFF69B 주소로 왜 갑자기 바뀌었을까요?
아래 5번 째 줄 코드에서 ttwu_do_activate 함수를 호출하기 직전 스택 주소는 0xEAD9DDE0이고.
1 NSR:C015597C|E1A00008 cpy r0,r8
2 NSR:C0155980|EB3ADE16 bl 0xC100D1E0 ; _raw_spin_lock
3 NSR:C0155984|E1A00008 cpy r0,r8
4 NSR:C0155988|E1A0100A cpy r1,r10 ; r1,p
5 NSR:C015598C|EBFFE3D7 bl 0xC014E8F0 ; ttwu_do_activate.constprop.52
ttwu_do_activate 함수의 어셈블리 코드를 보면 아래와 같이 r4, r5, r11, r14을 스택에 푸쉬합니다.
NSR:C014E8F0|E92D4830 ttwu_do_activate.constprop.52: push {r4-r5,r11,r14}
아래 스택 주소 0xEAD9DDE0 근처 메모리 덤프를 보면 7번, 8번, 9번 줄의 메모리 덤프와 같이 스택에 레지스터 값을 저장합니다. 그런데 5번 째 줄을 보면 R10이 0x0입니다. 원래 0xEB95AB80 이어야 하는데요.
1 NSD:EAD9DDC4| FF FF FF FF 0xFFFFFFFF \\vmlinux\mdss_mdp_pipe\mdss_mdp_pipe_assign\__out
2 NSD:EAD9DDC8| 51 00 00 00 0x51 \\vmlinux\sch_mqprio\__exitcall_mqprio_module_exit+0x1
3 NSD:EAD9DDCC| 1C E9 14 C0 0xC014E91C \\vmlinux\sched/core\ttwu_do_activate.constprop.52+0x2C
4 NSD:EAD9DDD0| 07 00 00 00 0x7 \\vmlinux\aesbs-glue\__exitcall_aesbs_mod_exit+0x3
5 NSD:EAD9DDD4| 00 00 00 00 0x0 // <<-- R10
6 NSD:EAD9DDD8| 3C DE D9 EA 0xEAD9DE3C // <<-- R11
7 NSD:EAD9DDDC| 90 59 15 C0 0xC0155990 \\vmlinux\sched/core\try_to_wake_up+0x394 //<<-- R14
8 NSD:EAD9DDE0| 40 2B A8 5F 0x5FA82B40
결국 아래 코드에서 스택 푸쉬를 이상하게 해서 발생한 문제로 보입니다.
NSR:C014E8F0|E92D4830 ttwu_do_activate.constprop.52: push {r4-r5,r11,r14}
# Reference: For more information on 'Linux Kernel';
디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 1
디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 2
'Core BSP 분석 > 커널 트러블슈팅' 카테고리의 다른 글
| [Kernel][Crash] 워크큐(workqueue) 락업(2) at [0321] (0) | 2023.05.07 |
|---|---|
| [Kernel][Crash][0320] 워크큐(workqueue) 락업(1) (0) | 2023.05.07 |
| [Kernel][Stability] tcp_v4_rcv -> __stack_chk_fail (0) | 2023.05.07 |
| [Linux][Kernel] data abort@cpuacct_charge - 리눅스 커널 (0) | 2023.05.07 |
| [Linux][Kernel] data abort@irq_affinity_notify - 리눅스 커널 (0) | 2023.05.07 |
