Linux Kernel(4.19) Hacks

rousalome.egloos.com

포토로그 Kernel Crash


통계 위젯 (화이트)

5112
737
82115


[Linux][Kernel] data abort@cpuacct_charge - 리눅스 커널 [Crash]Troubleshooting!!

#커널 크래시 디버깅 및 TroubleShooting

CPU3에서 실행 중인 "Binder:15701_2" 프로세스가 데이터 어보트로 커널 크래시가 발생했습니다.
커널 로그가 데이터 어보트 발생 시 어떤 동작을 했는지 레지스터 정보와 함께 알려주네요. 
[69350.929482] <26>Unable to handle kernel paging request at virtual address 11ad4e80
[69350.929511] <26>pgd = d57f0000
[69350.929527] <22>[11ad4e80] *pgd=00000000
[69350.929548] <6>Internal error: Oops: 5 [#1] PREEMPT SMP ARM
[69350.929563] <c2>Modules linked in: texfat(PO)
[69350.929590] <c6>CPU: 5 PID: 15728 Comm: Binder:15701_2 Tainted: P        W  O   3.18.71-ge77ee2f-00001-g0988851 #1
[69350.929608] <c6>task: d2fb2b80 ti: ce4f8000 task.ti: ce4f8000
[69350.929635] <c2>PC is at cpuacct_charge+0x30/0x58
[69350.929653] <c2>LR is at cpuacct_charge+0x1c/0x58
[69350.929671] <c2>pc : [<c01709a4>]    lr : [<c0170990>]    psr: 20070193
                   sp : ce4f9cb8  ip : 03bd1201  fp : ce4f9d9c
[69350.929695] <c2>r10: d2fb2b80  r9 : 000068cc  r8 : 00000005
[69350.929711] <c2>r7 : 00000000  r6 : 0016a175  r5 : e6188290  r4 : d2fb2b80
[69350.929727] <c2>r3 : e17bbe80  r2 : 30319000  r1 : e97bbe80  r0 : c1a0e538
[69350.929744] <c2>Flags: nzCv  IRQs off  FIQs on  Mode SVC_32  ISA ARM  Segment none
[69350.929760] <c2>Control: 10c0383d  Table: 957f006a  DAC: 00000051
[69350.929776] <6>Process Binder:15701_2 (pid: 15728, stack limit = 0xce4f8210)

크래시 유틸리티 프로그램으로 콜스택을 잡아 봤습니다. 아래와 같이 이쁘게 콜스택이 출력되네요.
함수 흐름을 살펴보면 IRQ가 Trigger된 후 current_thread_info의 preempt_count가 0이라 스케쥴링이 되었습니다.
svc_preempt -> preempt_schedule_irq -> __schedule
crash> bt -I C01709A4 -S  CE4F9CB8 d2fb2b80
PID: 15728  TASK: d2fb2b80  CPU: 5   COMMAND: "Binder:15701_2"
bt: WARNING:  stack address:0xce4f9da8, program counter:0xc0ff4658
 #0 [<c01709a4>] (cpuacct_charge) from [<c01592a8>]
 #1 [<c01592a8>] (update_curr) from [<c015c00c>]
 #2 [<c015c00c>] (put_prev_entity) from [<c015c61c>]
 #3 [<c015c61c>] (put_prev_task_fair) from [<c0167a14>]
 #4 [<c0167a14>] (pick_next_task_rt) from [<c0ff4364>]
 #5 [<c0ff4364>] (__schedule) from [<c0ff4e2c>]
 #6 [<c0ff4e2c>] (preempt_schedule_irq) from [<c0ff97d8>]
 #7 [<c0ff97d8>] (svc_preempt) from [<c039b9dc>]
 #8 [<c039b9e0>] (blk_flush_plug_list) from [<c039bd88>]
 #9 [<c039bd88>] (blk_finish_plug) from [<c02d3c44>]
#10 [<c02d3c44>] (ext4_writepages) from [<c01f0218>]
#11 [<c01f0218>] (__filemap_fdatawrite_range) from [<c01f0318>]
#12 [<c01f0318>] (filemap_write_and_wait_range) from [<c02caa4c>]
#13 [<c02caa4c>] (ext4_sync_file) from [<c0267980>]
#14 [<c0267980>] (vfs_fsync) from [<c0267a68>]
#15 [<c0267a68>] (do_fsync) from [<c0106a00>]
    pc : [<b1d5a520>]    lr : [<b0cb491b>]    psr: 80070010
    sp : a51a5cc0  ip : 00000000  fp : 00000000
    r10: 00000006  r9 : b001e400  r8 : 00000200
    r7 : 00000094  r6 : 00000000  r5 : 00000000  r4 : b001e5b8
    r3 : 00000000  r2 : b0cb4905  r1 : 00000002  r0 : 00000033
    Flags: Nzcv  IRQs on  FIQs on  Mode USER_32  ISA ARM

Trace32로 콜스택을 잡으면 더 직관적으로 디버깅 정보를 표현해줍니다.
__irq_svc 심볼이 콜스택에 보이는데요. 이는 IRQ가 Trigger될 시 프로그램 카운터가 이동하는 함수입니다.
__irq_svc -> svc_preempt -> preempt_schedule_irq -> __schedule
-000|cpuacct_charge()
-001|account_group_exec_runtime(inline)
-001|update_curr()
-002|check_spread(inline)
-002|put_prev_entity()
-003|put_prev_task_fair()
-004|pick_next_task_rt(inline)
-004|pick_next_task_rt()
-005|pick_next_task(inline)
-005|__schedule()
-006|arch_local_irq_disable(inline)
-006|preempt_schedule_irq()
-007|svc_preempt(asm)
-008|__irq_svc(asm)
 -->|exception
-009|blk_flush_plug_list()
-010|current_thread_info(inline)
-010|blk_finish_plug()
-011|ext4_writepages()
-012|__filemap_fdatawrite_range()
-013|filemap_write_and_wait_range()
-014|ext4_sync_file()
-015|vfs_fsync()
-016|fdput(inline)
-016|do_fsync()
-017|ret_fast_syscall(asm)

이제 커널 패닉이 왜 발생했는지 점검해봐야 겠습니다.
C01709A4 주소에서 커널 패닉이 일어났는데, 이 당시 r3은 e17bbe80  r2는 30319000입니다.
"ldrd    r4,r5,[r3,+r2]" 명령어는 r3에서 r2를 더한 주소의 메모리 덤프를 8바이트 만큼 r4, r5에 로딩합니다.
그런데, r2와 r3를 더하면 결과는 111AD4E80 인데, MMU에서 11AD4E80 주소를 물리 주소로 변환하지 못합니다.
NSR:C01709A0|E5913060                       ldr     r3,[r1,#0x60]    ; _________p1,[r1,#96]
NSR:C01709A4|E18340D2                      ldrd    r4,r5,[r3,+r2]  //<<-- 커널 패닉

그래서 커널 메시지가 아래 로그를 토해내는 것이죠.
[69350.929482] <26>Unable to handle kernel paging request at virtual address 11ad4e80
[69350.929511] <26>pgd = d57f0000

그럼, R3나 R2값이 잘못됐다고 볼 수 있고 이 레지스터들이 어떻게 실행됐는지 추적해봐야 합니다.
커널 소스를 열어서 보면, 커널 패닉이 발생한 코드는 아래 cpuacct_charge() 함수 247 라인 per_cpu_ptr(ca->cpuusage, cpu); 임을 알 수 있어요.
235void cpuacct_charge(struct task_struct *tsk, u64 cputime)
236{
237 struct cpuacct *ca;
238 int cpu;
239
240 cpu = task_cpu(tsk);
241
242 rcu_read_lock();
243
244 ca = task_ca(tsk);
245
246 while (true) {
247 u64 *cpuusage = per_cpu_ptr(ca->cpuusage, cpu);  //<<--
248 *cpuusage += cputime;

그럼 R2나 R3가 per-cpu offset 정보를 담고 있다고 봐야 하는데요.
__per_cpu_offset 변수를 보면 다섯 번째 per-cpu 오프셋이 0x30319000 이군요.
커널 패닉 발생 시 r2: 30319000은 정상 값이라고 봐야 겠습니다.
crash> p __per_cpu_offset
__per_cpu_offset = $3 =
 {0x302dd000, 0x302e9000, 0x302f5000, 0x30301000, 0x3030d000, 0x30319000, 0x30325000, 0x30331000}
NSR:C0170974|E92D4DF0  cpuacct_charge:      push    {r4-r8,r10-r11,r14}
NSR:C0170978|E1A07003                       cpy     r7,r3
NSR:C017097C|E5903004                       ldr     r3,[r0,#0x4]
NSR:C0170980|E1A04000                       cpy     r4,r0            ; r4,tsk
NSR:C0170984|E1A06002                       cpy     r6,r2
NSR:C0170988|E5938014                       ldr     r8,[r3,#0x14]
NSR:C017098C|EB004241                       bl      0xC0181298       ; __rcu_read_lock
NSR:C0170990|E594367C                       ldr     r3,[r4,#0x67C]  //<<--[1]
NSR:C0170994|E59F002C                       ldr     r0,0xC01709C8
NSR:C0170998|E593102C                       ldr     r1,[r3,#0x2C] //<<--[2]
NSR:C017099C|E7902108                       ldr     r2,[r0,+r8,lsl #0x2]
NSR:C01709A0|E5913060                       ldr     r3,[r1,#0x60]    ; _________p1,[r1,#96] //<<--[3]
NSR:C01709A4|E18340D2                      ldrd    r4,r5,[r3,+r2]  //<<--[4]

이제 R3가 e17bbe80으로 어떻게 업데이트 됐는지 추적해봐야 겠습니다. 위 어셈블리 코드를 분석 시작할께요.
[1]: R4: 0xD2FB2B80는 task descriptor 포인터를 가르키고 있는데, 0x67C 오프셋에 위치한 메모리 덤프 로딩을 실행합니다.
크래시 유틸리티 프로그램으로 확인하면 task_struct.cgroups 멤버에 접근하네요.
crash> struct -o task_struct.cgroups
struct task_struct {
  [0x67c] struct css_set *cgroups;
}

R3 = 0xDFB18800 = *D2FB31FC= *(0xD2FB2B80 + 0x67C) = *(R4 + 0x67C)
crash> struct task_struct.cgroups 0xD2FB2B80
  cgroups = 0xdfb18800

[2]: R1 = 0xE97BBE80 = *(0xDFB1882C) = *(0xDFB18800 + 0x2C) = *(R3 + 0x2C)
crash> rd 0xDFB1882C
dfb1882c:  e97bbe80  

[3]: R3 = 0xCECCA980 = *0xE97BBEE0  *(0xE97BBE80 + 0x60)  = *(R1 + 0x60)
crash> rd 0xE97BBEE0
e97bbee0:  cecca980 

[4]: 커널 패닉 발생 시 R3이 0xCECCA980값이 아니라 0xE17BBE80입니다.
#커널 패닉 시 메시지
[69350.929711] <c2>r7 : 00000000  r6 : 0016a175  r5 : e6188290  r4 : d2fb2b80
[69350.929727] <c2>r3 : e17bbe80  r2 : 30319000  r1 : e97bbe80  r0 : c1a0e538

다른 관점으로 cgroups 자료 구조를 분석해보면,
커널 패닉 시 cgroups 정보와 init_css_set 정보 확인 후 0xe97bbe80 메모리 덤프가 0xc1a1f480값 일 것 같은데요.
crash> struct css_set.subsys  0xdfb18800
  subsys = {0xc1bf2d58 <root_task_group>, 0xe97bbe80, 0xf15e5000, 0xf15e5080}
  
crash> struct css_set.subsys  0xc1a21a84
  subsys = {0xc1bf2d58 <root_task_group>, 0xc1a1f480 <root_cpuacct>, 0xf15e5000, 0xf15e5080}
  
crash> p &init_css_set
$4 = (struct css_set *) 0xc1a21a84 <init_css_set>

크래시 덤프 분석을 정리하면 아래와 2가지 이유 중 하나로 데이터 어보트가 생겼다고 추정할 수 있습니다.
1. @C01709A0 메모리 주소의 "ldr     r3,[r1,#0x60]" 명령어 오동작
2. struct css_set.subsys 멤버가 잘못된 주소를 가르키고 있음(0xc1a1f480 -> 0xe97bbe80)
.

핑백

덧글

댓글 입력 영역