Arm Linux Kernel Hacks

디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 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

#커널 크래시 디버깅 및 TroubleShooting

커널 패닉 시 아래 콜 스택이 남아 있습니다.

[39136682.663247] <IRQ> [<ffffffff816351f1>] dump_stack+0x19/0x1b

[39136682.663626] [<ffffffff8162ea6c>] panic+0xd8/0x1e7

[39136682.663988] [<ffffffff8158bd35>] ? tcp_v4_rcv+0x635/0x9f0

[39136682.664361] [<ffffffff8107b00b>] __stack_chk_fail+0x1b/0x20

[39136682.664743] [<ffffffff8158bd35>] tcp_v4_rcv+0x635/0x9f0

[39136682.665131] [<ffffffff8163d0ed>] common_interrupt+0x6d/0x6d

[39136682.665529] <EOI> [<ffffffff81645a2b>] ? sysret_audit+0x17/0x21

위 콜 스택을 보면 여러가지 의문이 생기는데요.

1> tcp_v4_rcv이 인터럽트 핸들러로 호출되는 것 처럼 보이는데, 다른 인터럽트 핸들러도 위와 같은 콜 스택이 확인되나요?

다른 인터럽트 핸들러가 호출될 때와 다른 콜스택이면 스택 Corruption을 의심할 수 있습니다.

2> 커널 패닉이 발생했을 때 RSP 즉 스택 주소(00002aaec5008b98)가 이상합니다.

커널 프로세스의 스택 주소는 struct task_struct->stack -- (struct task_struct->stack)+0x4000 사이이어야 합니다.

crash> bt

PID: 168037 TASK: ffff880494923980 CPU: 26 COMMAND: "app01"

#0 [ffff88046f3a3db8] machine_kexec at ffffffff81051beb

#1 [ffff88046f3a3e18] crash_kexec at ffffffff810f2542

#2 [ffff88046f3a3ee8] panic at ffffffff8162ea73

#3 [ffff88046f3a3f68] __stack_chk_fail at ffffffff8107b00b

#4 [ffff88046f3a3f78] tcp_v4_rcv at ffffffff8158bd35

--- <IRQ stack> ---

#5 [ffff880217dbbf58] ret_from_intr at ffffffff8163d0ed

RIP: 00002aae21629848 RSP: 00002aaec5008b98 RFLAGS: 00000202

RAX: 00002aaf8c0394c0 RBX: ffffffff81645a2b RCX: 0000000000038400

RDX: 0000000000038180 RSI: 00002aaf68157390 RDI: 00002aaf8c0716c0

RBP: 00002aaec5009180 R8: 00002aaf8c0718b0 R9: 0000000000000000

R10: 0000000000000002 R11: 00002aae21657160 R12: 0000000000000000

R13: 00002aaec500a700 R14: 00002aaec500a9c0 R15: 0000000000000000

ORIG_RAX: ffffffffffffffca CS: 0033 SS: 002b

아래 명령어로 스택 주소를 확인해보세요.

struct task_struct.stack ffff880494923980

예)

crash64> struct task_struct.stack ffffffc001580e40

stack = 0xffffffc001574000 <init_thread_union>

3> 만약 2>에서 언급된 것과 같이 스택이 꺠져 있다면, 아래 방법으로 tcp_v4_rcv 함수 내에서 호출되는 함수 전 후로 로그를 확인해도 좋을 것 같습니다.

http://rousalome.egloos.com/9969790

4> 커널 Makefile을 보면 -fstack-protector 옵션이 켜져 있을 때 스택 카나리 코드가 추가됩니다. 아래 옵션을 한 번 끄고 어떤 동작을 하는 지 점검해도 좋을 것 같습니다.

ifdef CONFIG_CC_STACKPROTECTOR_REGULAR

stackp-flag := -fstack-protector

ifeq ($(call cc-option, $(stackp-flag)),)

$(warning Cannot use CONFIG_CC_STACKPROTECTOR_REGULAR: \

-fstack-protector not supported by compiler)

endif

else

ifdef CONFIG_CC_STACKPROTECTOR_STRONG

stackp-flag := -fstack-protector-strong

ifeq ($(call cc-option, $(stackp-flag)),)

$(warning Cannot use CONFIG_CC_STACKPROTECTOR_STRONG: \

-fstack-protector-strong not supported by compiler)

endif

else

# Force off for distro compilers that enable stack protector by default.

stackp-flag := $(call cc-option, -fno-stack-protector)

# Reference: For more information on 'Linux Kernel';

디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 1

디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 2

'Core BSP 분석 > 커널 트러블슈팅' 카테고리의 다른 글

[Kernel][Crash][0320] 워크큐(workqueue) 락업(1) (0)	2023.05.07
[Kernel][Panic] panic@ttwu_do_activate (메모리 불량 보드) (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
[Linux][Kernel] data abort @tty_wakeup - 리눅스 커널 (0)	2023.05.07

#커널 크래시 디버깅 및 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)

# Reference: For more information on 'Linux Kernel';

디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 1

디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 2

'Core BSP 분석 > 커널 트러블슈팅' 카테고리의 다른 글

[Kernel][Panic] panic@ttwu_do_activate (메모리 불량 보드) (0)	2023.05.07
[Kernel][Stability] tcp_v4_rcv -> __stack_chk_fail (0)	2023.05.07
[Linux][Kernel] data abort@irq_affinity_notify - 리눅스 커널 (0)	2023.05.07
[Linux][Kernel] data abort @tty_wakeup - 리눅스 커널 (0)	2023.05.07
watchdog reset - race in ipv6_ifa_notify() - 리눅스 커널 (0)	2023.05.07

#커널 크래시 디버깅 및 TroubleShooting

아래 커널 로그와 함께 시스템이 커널 패닉으로 돌아가셨어요.

irq_affinity_notify+0x4c 란 함수에서 data abort가 난 것을 확인할 수 있어요.

[287229.435076] <c6>mmc0: mmc_start_bkops: raw_bkops_status=0x2, from_exception=1

[287230.328287] <c6>mmc0: mmc_start_bkops: Starting bkops

[287231.319886] <26>Unable to handle kernel NULL pointer dereference at virtual address 000000fc

[287231.319920] <26>pgd = c0004000

[287231.319936] <22>[000000fc] *pgd=00000000

[287231.319957] <6>Internal error: Oops: 5 [#1] PREEMPT SMP ARM

[287231.319974] <c2>Modules linked in: core_ctl(PO)

[287231.320000] <c6>CPU: 2 PID: 13 Comm: kworker/1:0 Tainted: P W O 3.10.49-gca5eb64 #1

[287231.320028] <c2>Workqueue: events irq_affinity_notify

[287231.320046] <c6>task: e0063fc0 ti: e01f2000 task.ti: e01f2000

[287231.320065] <c2>PC is at irq_affinity_notify+0x4c/0xf8

[287231.320083] <c2>LR is at pm_qos_update_target+0x20c/0x240

[287231.320102] <c2>pc : [<c006c194>] lr : [<c0068ce0>] psr: 00000013

코어 덤프를 올려서 왜 커널 패닉이 발생했는지 조금 더 살펴볼까요?

우선 crash-utility 프로그램으로 콜스택을 살펴보면 c006c194란 프로그램 카운터에서 data abort가 발생했음을 알 수 있어요.

crash> bt -I C0008400 -S E01F3DF0 0xE0063FC0

PID: 13 TASK: e0063fc0 CPU: 2 COMMAND: "kworker/1:0"

#0 [<c0008400>] (do_DataAbort) from [<c000d958>]

pc : [<c006c194>] lr : [<c0068ce0>] psr: 00000013

sp : e01f3ee0 ip : 00000004 fp : 00000000

r10: 00000000 r9 : c4826700 r8 : e0009a24

r7 : c0069124 r6 : e01f3ee4 r5 : 000000f8 r4 : ded06564

r3 : 00000100 r2 : e01f3e98 r1 : 60000013 r0 : 00000000

Flags: nzcv IRQs on FIQs on Mode SVC_32 ISA ARM

#1 [<c000d958>] (__dabt_svc) from [<c0068ce0>]

#2 [<c006c194>] (irq_affinity_notify) from [<c004248c>]

#3 [<c004248c>] (process_one_work) from [<c004320c>]

#4 [<c004320c>] (worker_thread) from [<c0047b10>]

#5 [<c0047b10>] (kthread) from [<c000de98>]

그럼 어떤 흐름으로 data abort가 일어났는지, 어셈블 코드 레벨로 디버깅을 좀 해보려고 해요.

이제 시작해볼까요?

1]: R7= *desc, (코드): struct irq_desc *desc = container_of(work, struct irq_desc, affinity_work);

[2]: 파라미터 struct work_struct *work를 r4에 저장

[3]: R8 = 0xE0009A24 = irq_desc.affinity_notify값, where: offsetof(struct irq_desc,affinity_notify) = 0x64

[4]: irq_desc.affinity_notify 주소를 가져오는데 where r5는 0xE0009A24이어야 하죠

[5]: r3 = 0x100, r8 = 0xE0009A24

[6]: list_for_each_entry() loop에 진입하면 안됨

[7]: "ldr r3, [r5, #4]" instruction의 base 주소 r5가 0xf8라서 Data Abort 발생

커널 로그(Unable to handle kernel NULL pointer dereference at virtual address 000000fc)에서 똑같은 정보를 확인할 수 있어요.

0xc006c148 <irq_affinity_notify>: push {r0, r1, r4, r5, r6, r7, r8, lr}

0xc006c14c <irq_affinity_notify+0x4>: subs r7, r0, #108 ; 0x6c //<<--[1]

0xc006c150 <irq_affinity_notify+0x8>: mov r4, r0 //<<--[2]

0xc006c154 <irq_affinity_notify+0xc>: beq 0xc006c234 <irq_affinity_notify+236>

0xc006c158 <irq_affinity_notify+0x10>: add r5, r7, #88 ; 0x58

0xc006c15c <irq_affinity_notify+0x14>: add r6, sp, #8

0xc006c160 <irq_affinity_notify+0x18>: add r8, r7, #100 ; 0x64 //<<--[3]

0xc006c164 <irq_affinity_notify+0x1c>: mov r0, r5

0xc006c168 <irq_affinity_notify+0x20>: bl 0xc0a34ca0 <_raw_spin_lock_irqsave>

0xc006c16c <irq_affinity_notify+0x24>: ldr r3, [r4, #-72] ; 0x48

0xc006c170 <irq_affinity_notify+0x28>: str r3, [r6, #-4]!

0xc006c174 <irq_affinity_notify+0x2c>: mov r1, r0

0xc006c178 <irq_affinity_notify+0x30>: mov r0, r5

0xc006c17c <irq_affinity_notify+0x34>: bl 0xc0a35028 <_raw_spin_unlock_irqrestore>

0xc006c180 <irq_affinity_notify+0x38>: ldr r5, [r4, #-8] //<<--[4]

0xc006c184 <irq_affinity_notify+0x3c>: sub r5, r5, #8

0xc006c188 <irq_affinity_notify+0x40>: add r3, r5, #8

0xc006c18c <irq_affinity_notify+0x44>: cmp r3, r8 //<<--[5]

0xc006c190 <irq_affinity_notify+0x48>: beq 0xc006c234 <irq_affinity_notify+236> //<<--[6]

0xc006c194 <irq_affinity_notify+0x4c>: ldr r3, [r5, #4] //<<--[7]

해당 C 코드는 아래와 같은데요. 참 신기하죠. &desc->affinity_notify가 NULL인데,

list_for_each_entry(notify, &desc->affinity_notify, list) 를 뚫고 들어가 실행을 한거란 말이죠.

static void irq_affinity_notify(struct work_struct *work)

{

struct irq_desc *desc =

container_of(work, struct irq_desc, affinity_work);

cpumask_var_t cpumask;

unsigned long flags;

struct irq_affinity_notify *notify;

// .. snip..

list_for_each_entry(notify, &desc->affinity_notify, list) { //<<--

if (!kref_get_unless_zero(&notify->kref))

continue;

notify->notify(notify, cpumask);

kref_put(&notify->kref, notify->release);

}

mutex_unlock(&desc->notify_lock);

free_cpumask_var(cpumask);

}

(To Be continue)

# Reference: For more information on 'Linux Kernel';

디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 1

디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 2

'Core BSP 분석 > 커널 트러블슈팅' 카테고리의 다른 글

[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 @tty_wakeup - 리눅스 커널 (0)	2023.05.07
watchdog reset - race in ipv6_ifa_notify() - 리눅스 커널 (0)	2023.05.07
tombstone - __strlen_chk (0)	2023.05.07

#커널 크래시 디버깅 및 TroubleShooting

USB와 TTY Driver 관련한 커널 패닉 디버깅 정보를 좀 공유하고자 해요.

아래 Signature로 커널 패닉이 발생했는데요. __irq_usr -> gic_handle_irq 코드 흐름으로 보아 유저 공간에서 실행 중인 프로세스로 IRQ가 Trigger되었다는 정보를 확인할 수 있어요.

바꾸어 말하면 아래 콜스택은 IRQ Context라고 할 수 있죠. 문제가 발생한 보드는 Mediatek MT6755랍니다.

[<c001df40>] do_page_fault+0x338/0x3f8

[<c0008544>] do_DataAbort+0x38/0x98

[<c0015058>] __dabt_svc+0x38/0x60

[<c031a5a0>] tty_wakeup+0xc/0x64

[<c06f82ec>] gs_start_io+0x94/0xf4

[<c06f8698>] gserial_connect+0xe0/0x180

[<c06f7578>] acm_set_alt+0x88/0x1a8

[<c06f3c5c>] composite_setup+0xd34/0x1520

[<c070d154>] android_setup+0x1f4/0x1fc

[<c03fc6e8>] forward_to_driver+0x64/0x100

[<c03fd418>] musb_g_ep0_irq+0x7d8/0x1c18

[<c03fb094>] musb_interrupt+0x94/0xc78

[<c04024f0>] generic_interrupt+0xc34/0x1218

[<c009b020>] handle_irq_event_percpu+0xe0/0x2e4

[<c009b268>] handle_irq_event+0x44/0x64

[<c009df54>] handle_fasteoi_irq+0xe8/0x1a4

[<c009a7dc>] __handle_domain_irq+0x104/0x264

[<c0008668>] gic_handle_irq+0x2c/0x64

[<c00153a8>] __irq_usr+0x48/0x60

비슷한 시기에 nVidia Tegra4i SoC에서 아래 커널 로그와 함께 크래시가 발생했어요.

Tegra4i에서 정의한 OTG IRQ를 처리하는 함수만 다르지 처리되는 함수 흐름은 똑같네요.

[71653.259161 08-15 11:27:39.779] android_work: did not send uevent (0 0 (null))

[71653.290526 08-15 11:27:39.811] android_work: sent uevent USB_STATE=CONNECTED

[71653.292844 08-15 11:27:39.813] android_work: sent uevent USB_STATE=DISCONNECTED

[71653.365187 08-15 11:27:39.885] android_usb gadget: high speed config #1: android

[71653.365758 08-15 11:27:39.885] Unable to handle kernel NULL pointer dereference at virtual address 000000a8

[71653.365775 08-15 11:27:39.885] pgd = c0004000

[71653.365785 08-15 11:27:39.885] [000000a8] *pgd=00000000

[71653.365805 08-15 11:27:39.885] Internal error: Oops: 5 [#1] PREEMPT SMP ARM

[71653.365841 08-15 11:27:39.885] Modules linked in: bcmdhd(O)

[71653.365864 08-15 11:27:39.885] CPU: 0 Tainted: G O (3.4.65-g000d394 #1)

[71653.365891 08-15 11:27:39.885] PC is at tty_wakeup+0x14/0x80

[71653.365910 08-15 11:27:39.885] LR is at gs_start_io+0x90/0xe8

[71653.365922 08-15 11:27:39.885] pc : [<c03b2fe8>] lr : [<c04a2520>] psr: 20030193

[71653.365928 08-15 11:27:39.885] sp : d2b2db10 ip : d2b2db28 fp : d2b2db24

[71653.365944 08-15 11:27:39.885] r10: e29ba318 r9 : e29ba324 r8 : 00000000

[71653.365955 08-15 11:27:39.885] r7 : e29ba2f4 r6 : e16290a8 r5 : e29ba2e8 r4 : e29ba2c0

[71653.365967 08-15 11:27:39.885] r3 : 0000000a r2 : 00000000 r1 : 60030193 r0 : 00000000

[71653.365984 08-15 11:27:39.885] Flags: nzCv IRQs off FIQs on Mode SVC_32 ISA ARM Segment kernel

[71653.365996 08-15 11:27:39.885] Control: 10c5387d Table: 8567c04a DAC: 00000015

// ... 생략...

[71653.369827 08-15 11:27:39.885] [<c03b2fe8>] (tty_wakeup+0x14/0x80) from [<c04a2520>] (gs_start_io+0x90/0xe8)

[71653.369848 08-15 11:27:39.885] [<c04a2520>] (gs_start_io+0x90/0xe8) from [<c04a2f24>] (gserial_connect+0xdc/0x164)

[71653.369865 08-15 11:27:39.885] [<c04a2f24>] (gserial_connect+0xdc/0x164) from [<c04a3440>] (acm_set_alt+0x90/0x1ac)

[71653.369883 08-15 11:27:39.885] [<c04a3440>] (acm_set_alt+0x90/0x1ac) from [<c04995b4>] (composite_setup+0x244/0xf80)

[71653.369899 08-15 11:27:39.885] [<c04995b4>] (composite_setup+0x244/0xf80) from [<c049a3b0>] (android_setup+0xc0/0x154)

[71653.369921 08-15 11:27:39.885] [<c049a3b0>] (android_setup+0xc0/0x154) from [<c0487d44>] (tegra_udc_irq+0xbd4/0x11d0)

[71653.369944 08-15 11:27:39.885] [<c0487d44>] (tegra_udc_irq+0xbd4/0x11d0) from [<c00e64a8>] (handle_irq_event_percpu+0x88/0x2ec)

[71653.369962 08-15 11:27:39.885] [<c00e64a8>] (handle_irq_event_percpu+0x88/0x2ec) from [<c00e6758>] (handle_irq_event+0x4c/0x6c)

[71653.369980 08-15 11:27:39.885] [<c00e6758>] (handle_irq_event+0x4c/0x6c) from [<c00e96ec>] (handle_fasteoi_irq+0xcc/0x174)

[71653.369998 08-15 11:27:39.885] [<c00e96ec>] (handle_fasteoi_irq+0xcc/0x174) from [<c00e5c28>] (generic_handle_irq+0x3c/0x50)

[71653.370022 08-15 11:27:39.885] [<c00e5c28>] (generic_handle_irq+0x3c/0x50) from [<c000f9c4>] (handle_IRQ+0x5c/0xbc)

[71653.370040 08-15 11:27:39.885] [<c000f9c4>] (handle_IRQ+0x5c/0xbc) from [<c0008504>] (gic_handle_irq+0x34/0x68)

[71653.370057 08-15 11:27:39.885] [<c0008504>] (gic_handle_irq+0x34/0x68) from [<c000ec00>] (__irq_svc+0x40/0x70)

[71653.370070 08-15 11:27:39.885] Exception stack(0xd2b2dd80 to 0xd2b2ddc8)

이번에는 모바일계의 맞형 퀄컴님의 MSM8917 보드에서 똑같이 크래시가 발생했어요.

커널 로그는 아래와 같은데 똑같이 tty_wakeup() 함수에서 NULL pointer dereference로 크래시가 발생했네요.

[ 51.610867 / 01-01 11:22:44.521][1] cfg80211: Invalid regulatory domain detected:

[ 52.471153 / 01-01 11:22:45.381][0] Unable to handle kernel NULL pointer dereference at virtual address 000001cc

[ 52.471172 / 01-01 11:22:45.381][0] pgd = d04f4000

[ 52.471183 / 01-01 11:22:45.381][0] [000001cc] *pgd=00000000

[ 52.471198 / 01-01 11:22:45.381][0] Internal error: Oops: 5 [#1] PREEMPT SMP ARM

[ 52.471209 / 01-01 11:22:45.381][0] Modules linked in: texfat(PO)

[ 52.471228 / 01-01 11:22:45.381][0] CPU: 0 PID: 1026 Comm: rild Tainted: P W O 3.18.31-gadfe554 #1

[ 52.471240 / 01-01 11:22:45.381][0] task: e8ffb3c0 ti: d076e000 task.ti: d076e000

[ 52.471260 / 01-01 11:22:45.381][0] PC is at tty_wakeup+0x8/0x58

[ 52.471275 / 01-01 11:22:45.381][0] LR is at gs_start_io+0xb8/0xfc

[ 52.471288 / 01-01 11:22:45.381][0] pc : [<c04f534c>] lr : [<c06f364c>] psr: 20000193

[ 52.471288 / 01-01 11:22:45.381][0] sp : d076fd70 ip : 0000000b fp : ec6ebc80

[ 52.471305 / 01-01 11:22:45.381][0] r10: e97b5d84 r9 : e97b5d90 r8 : 00000000

[ 52.471316 / 01-01 11:22:45.381][0] r7 : c42a63b0 r6 : e97b5d58 r5 : e97b5d64 r4 : 00000000

[ 52.471328 / 01-01 11:22:45.381][0] r3 : e885e400 r2 : 00000000 r1 : 00320031 r0 : 00000000

//..

[ 52.471712 / 01-01 11:22:45.381][0] [<c04f534c>] (tty_wakeup) from [<c06f364c>] (gs_start_io+0xb8/0xfc)

[ 52.471729 / 01-01 11:22:45.381][0] [<c06f364c>] (gs_start_io) from [<c06f37d4>] (gserial_connect+0x144/0x1b0)

[ 52.471745 / 01-01 11:22:45.381][0] [<c06f37d4>] (gserial_connect) from [<c06f22ec>] (acm_set_alt+0x1e8/0x248)

[ 52.471760 / 01-01 11:22:45.381][0] [<c06f22ec>] (acm_set_alt) from [<c06efa1c>] (composite_setup+0x1448/0x159c)

[ 52.471778 / 01-01 11:22:45.381][0] [<c06efa1c>] (composite_setup) from [<c0725390>] (android_setup+0x124/0x1ac)

[ 52.471796 / 01-01 11:22:45.381][0] [<c0725390>] (android_setup) from [<c074967c>] (msm_udc_irq+0xd78/0xfb0)

[ 52.471813 / 01-01 11:22:45.381][0] [<c074967c>] (msm_udc_irq) from [<c016f7e4>] (handle_irq_event_percpu+0xb4/0x2ac)

[ 52.471829 / 01-01 11:22:45.381][0] [<c016f7e4>] (handle_irq_event_percpu) from [<c016fa18>] (handle_irq_event+0x3c/0x5c)

[ 52.471845 / 01-01 11:22:45.381][0] [<c016fa18>] (handle_irq_event) from [<c01727b8>] (handle_fasteoi_irq+0xb0/0x128)

[ 52.471863 / 01-01 11:22:45.381][0] [<c01727b8>] (handle_fasteoi_irq) from [<c016ef6c>] (generic_handle_irq+0x20/0x30)

[ 52.471880 / 01-01 11:22:45.381][0] [<c016ef6c>] (generic_handle_irq) from [<c016f230>] (__handle_domain_irq+0x7c/0xa0)

[ 52.471897 / 01-01 11:22:45.381][0] [<c016f230>] (__handle_domain_irq) from [<c01005c4>] (gic_handle_irq+0x48/0x78)

[ 52.471916 / 01-01 11:22:45.381][0] [<c01005c4>] (gic_handle_irq) from [<c0f3a004>] (__irq_usr+0x44/0x60)

3개의 다른 SoC에서 다른 콜스택으로 호출되어 결국 똑같은 함수에서 Data Abort가 발생한 게 신기하죠?

이제 덤프를 분석해야 할 시간이에요.

커널 패닉이 일어난 코드를 열여서 확인해보니,

tty_wakeup() 함수로 전달되는 파라미터 struct tty_struct *tty 가 NULL이라 데이터 Abort가 발생한 것처럼 보이는데요.

void tty_wakeup(struct tty_struct *tty)

{

struct tty_ldisc *ld;

if (test_bit(TTY_DO_WRITE_WAKEUP, &tty->flags)) { // <<-- kernel panic

ld = tty_ldisc_ref(tty);

struct tty_struct *tty 파라미터를 어떤 함수가 호출하는지 점검할 필요가 있어 보여요.

그럼 tty_wakeup() 함수를 어느 함수가 호출했는지 찾아가 보면, gs_start_io() 함수에서 port->port.tty 파라미터를 전달하고 있군요. port->port.tty 변수가 NULL인 것이 문제죠.

(struct gs_port *)0xE97B5C00 = 0xE97B5C00 -> (

port = (

buf = (head = 0xE97B5C40, work = (data = (counter = 0xFFFFFFE0), entry = (

tty = 0x0, // <<--

itty = 0x0,

ops = 0x0,

lock = (rlock = (raw_lock = (slock = 0x0, tickets = (owner = 0x0, next = 0

blocked_open = 0x0,

해당 코드는 아래와 같아요.

static int gs_start_io(struct gs_port *port)

{

// .. skip ..

/* unblock any pending writes into our circular buffer */

if (started) {

tty_wakeup(port->port.tty); //<<--

} else {

gs_free_requests(ep, head, &port->read_allocated);

gs_free_requests(port->port_usb->in, &port->write_pool,

&port->write_allocated);

status = -EIO;

}

그런데 커널 패닉이 일어나기 전 커널 로그를 아주 자세히 관찰해보면, 아래 커널 로그를 확인할 수가 있어요.

gs_close() 함수가 호출되었다는 정보를 확인할 수 있는데요.

[ 6285.082083 / 06-01 11:43:40.318] -(4)[981:mdl_sock_host]gs_close: ttyGS1 (d3681900,d7e1ca80) ...

커널 로그에 위 로그에 매핑되는 코드를 찾아가 보면 gs_close() 함수를 확인할 수 있어요.

이 함수에서 port->port.tty 변수를 NULL로 설정하는군요.

static void gs_close(struct tty_struct *tty, struct file *file)

{

struct gs_port *port = tty->driver_data;

struct gserial *gser;

// ..skip..

if (gser == NULL)

gs_buf_free(&port->port_write_buf);

else

gs_buf_clear(&port->port_write_buf);

tty->driver_data = NULL;

port->port.tty = NULL; //<<--

정리하면, USB단에서 USB OTG IRQ가 떠서 RX 패킷을 받아서 tty layer로 넘겨주려고 tty port를 wakeup 하는 동작에서 tty port가 close 되었군요.

아래 조건으로 race condition이 발생했음을 알 수 있어요.

CPU0 CPU1

-gs_close

port->port.tty = NULL 설정

IRQ Trigger

gs_start_io+0x94/0xf4

tty_wakeup+0xc/0x64

커널 패닉

그럼 아래 패치를 적용해서 평소 어떤 흐름으로, gs_close() 함수가 호출되는지 확인해볼까요?

diff --git a/drivers/usb/gadget/function/u_serial.c b/drivers/usb/gadget/function/u_serial.c

index d0b519d..d5cc9f1 100644

--- a/drivers/usb/gadget/function/u_serial.c

+++ b/drivers/usb/gadget/function/u_serial.c

@@ -789,6 +789,10 @@ static int gs_start_io(struct gs_port *port)

if (!port->port_usb)

return -EIO;

+

+ show_stack(NULL, NULL);

+ printk("[+][flash][%s][%s,%d]: caller: (%pS)\n", current->comm, __func__,__LINE__, (void *)__builtin_return_address(0));

+

/* unblock any pending writes into our circular buffer */

if (started) {

@@ -982,6 +986,9 @@ static void gs_close(struct tty_struct *tty, struct file *file)

tty->driver_data = NULL;

port->port.tty = NULL;

+ show_stack(NULL, NULL);

+ printk("[+][flash][%s][%s,%d]: caller: (%pS)\n", current->comm, __func__,__LINE__, (void *)__builtin_return_address(0));

+

port->openclose = false;

pr_debug("gs_close: ttyGS%d (%pK,%pK) done!\n",

아래와 같은 커널 로그를 확인할 수 있어요.

tty driver를 등록한 프로세스가 종료될 때 tty_release -> gs_close 순서로 함수가 호출되고 있네요.

<6>[ 172.692835 / 01-06 19:00:22.975][5] [<c0016f78>] (unwind_backtrace) from [<c0013720>] (show_stack+0x20/0x24)

<6>[ 172.692877 / 01-06 19:00:22.975][5] [<c0013720>] (show_stack) from [<c067a3b8>] (gs_close+0x1c8/0x258)

<6>[ 172.692910 / 01-06 19:00:22.975][5] [<c067a3b8>] (gs_close) from [<c045d16c>] (tty_release+0x148/0x4cc)

<6>[ 172.692941 / 01-06 19:00:22.975][5] [<c045d16c>] (tty_release) from [<c015b708>] (__fput+0x104/0x1e4)

<6>[ 172.692969 / 01-06 19:00:22.975][5] [<c015b708>] (__fput) from [<c015b85c>] (____fput+0x18/0x1c)

<6>[ 172.693004 / 01-06 19:00:22.975][5] [<c015b85c>] (____fput) from [<c0049240>] (task_work_run+0xc4/0xf0)

<6>[ 172.693038 / 01-06 19:00:22.975][5] [<c0049240>] (task_work_run) from [<c0012f40>] (do_work_pending+0xb8/0xd0)

<6>[ 172.693069 / 01-06 19:00:22.975][5] [<c0012f40>] (do_work_pending) from [<c000f320>] (work_pending+0xc/0x20)

<6>[ 172.693092 / 01-06 19:00:22.975][5] [+][flash][atd][gs_close,990]: caller: (tty_release+0x148/0x4cc)

그럼 어떻게 예외 처리 코드를 추가하면 좋을까요?

아래와 같은 패치 코드를 작성하여 예외처리 루틴을 추가했더니 이 현상은 사라졌어요. port->port.tty이 null 포인터가 아닐 때만 tty_wakeup(port->port.tty); 함수를 호출하는거죠.

diff --git a/drivers/usb/gadget/function/u_serial.c b/drivers/usb/gadget/function/u_serial.c

index 2610e22..4c28a25 100644

--- a/drivers/usb/gadget/function/u_serial.c

+++ b/drivers/usb/gadget/function/u_serial.c

@@ -790,7 +790,11 @@ static int gs_start_io(struct gs_port *port)

if (!port->port_usb)

return -EIO;

/* unblock any pending writes into our circular buffer */

- if (started) {

+ if (started && port->port.tty) {

tty_wakeup(port->port.tty);

} else {

gs_free_requests(ep, head, &port->read_allocated);

# Reference: For more information on 'Linux Kernel';

디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 1

디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 2

https://patchwork.kernel.org/patch/8147541/

'Core BSP 분석 > 커널 트러블슈팅' 카테고리의 다른 글

[Linux][Kernel] data abort@cpuacct_charge - 리눅스 커널 (0)	2023.05.07
[Linux][Kernel] data abort@irq_affinity_notify - 리눅스 커널 (0)	2023.05.07
watchdog reset - race in ipv6_ifa_notify() - 리눅스 커널 (0)	2023.05.07
tombstone - __strlen_chk (0)	2023.05.07
Kernel][Panic] 메모리 불량 커널 크래시@find_vma_links - 1 (0)	2023.05.07

#커널 크래시 디버깅 및 TroubleShooting

예전 MTK SoC에서 일어났던 Watchdog Reset 이슈인데요. 디버깅 정보를 조금 공유하고자 해요.

CPU1에서 수행 중인 "migration/1" process에서 watchdog reset이 발생하여 시스템이 리셋된 흔적을 확인할 수 있어요.

-000|do_undefinstr()

-001|__und_svc_fault(asm)

-->|exception

-002|aee_wdt_atf_info()

-003|aee_wdt_atf_entry()

-004|debug_smp_processor_id()

-005|cpu_stopper_thread()

-006|smpboot_thread_fn()

-007|kthread()

-008|ret_from_fork(asm)

-009|ret_fast_syscall(asm)

MTK SoC에서는 각 CPU가 Hotplug 동작 전 후에서 Watchdog Kick 여부를 파악하는데요.

cpus_kick_bit 변수는 hotplugin을 수행 요청을 한 CPU의 비트마스크이고, kick_bit은 hotplugin 동작 완료 시 notifier call이 수행된 CPU 비트 필드를 보여줘요.

11110011 (where) cpus_kick_bit = 0xF3

00000000 (where)kick_bit = 0x0

그럼 위 정보로 보아, CPU0/1/4/5/6/7에서 무엇인가 Stuck이 되어 Watchdog Kick을 못했다고 추정할 수 있어요.

각 CPU의 콜스택을 점검해보니 CPU4에서 "kworker/4:3" 프로세스가 아래 콜스택으로 구동 중임을 알 수 있어요.

-000|__ipv6_dev_ac_inc()

-001|addrconf_join_anycast()

-002|__ipv6_ifa_notify()

-003|local_bh_enable(inline)

-003|rcu_read_unlock_bh(inline)

-003|ipv6_ifa_notify()

-004|addrconf_dad_begin(inline)

-004|addrconf_dad_work()

-005|static_key_count(inline)

-005|static_key_false(inline)

-005|trace_workqueue_execute_end(inline)

-005|process_one_work()

-006|list_empty(inline)

-006|worker_thread()

-007|kthread()

-008|ret_from_fork(asm)

-009|ret_fast_syscall(asm)

그럼 ftrace log로 실제 각 CPU별로 어떤 동작을 수행 중이었는 지 살펴보도록 할께요.

우선 CPU4에서 어떤 동작이 있었는지 살펴보면, "kworker/4:3-10711" 프로세스가 addrconf_dad_work work를 수행 중인 로그가 확인되요.

그런데, workqueue_execute_end 0xd8c3cb7c란 로그가 안 보이는 것으로 보아 위에 제가 잡은 콜스택 정보와 일치하는 정보이군요.

addrconf_dad_work -> ipv6_ifa_notify -> __ipv6_ifa_notify -> addrconf_join_anycast

그리고 마지막 ftrace로그의 타임 스탬프는 1595.644768로 확인되거든요. CPU4가 22초 동안 preemption되지 않고 stuck되었다는 정보를 확인할 수 있죠.

kworker/4:3-10711 [004] 1573.162047: workqueue_execute_start: work struct 0xd8c3cb7c: function addrconf_dad_work

kworker/4:3-10711 [004] 1573.162099: sched_migrate_task: comm=dnsmasq pid=11779 prio=120 orig_cpu=5 dest_cpu=6 state=W

kworker/4:3-10711 [004] 1573.162114: sched_wakeup: comm=dnsmasq pid=11779 prio=120 success=1 target_cpu=006 state=W

kworker/4:3-10711 [004] 1573.162128: sched_wakeup: comm=vpnclientd pid=2786 prio=120 success=1 target_cpu=004 state=W

kworker/4:3-10711 [004] 1573.162136: sched_migrate_task: comm=netd pid=1145 prio=120 orig_cpu=5 dest_cpu=4 state=W

kworker/4:3-10711 [004] 1573.162140: sched_wakeup: comm=netd pid=1145 prio=120 success=1 target_cpu=004 state=W

kworker/4:3-10711 [004] 1573.164771: irq_handler_entry: irq=30 name=arch_timer

kworker/4:3-10711 [004] 1573.164795: irq_handler_exit: irq=30 ret=handled

kworker/4:3-10711 [004] 1573.170639: irq_handler_entry: irq=216 name=ovl0

kworker/4:3-10711 [004] 1573.170651: irq_handler_exit: irq=216 ret=handled

kworker/4:3-10711 [004] 1573.170771: irq_handler_entry: irq=218 name=rdma0

kworker/4:3-10711 [004] 1573.170789: sched_wakeup: comm=VSyncThread_0 pid=455 prio=112 success=1 target_cpu=006 state=W

kworker/4:3-10711 [004] 1573.170792: irq_handler_exit: irq=218 ret=handled

kworker/4:3-10711 [004] 1573.174770: irq_handler_entry: irq=30 name=arch_timer

kworker/4:3-10711 [004] 1573.174786: irq_handler_exit: irq=30 ret=handled

kworker/4:3-10711 [004] 1573.175936: irq_handler_entry: irq=209 name=mutex

kworker/4:3-10711 [004] 1573.175944: irq_handler_exit: irq=209 ret=handled

kworker/4:3-10711 [004] 1573.176141: irq_handler_entry: irq=270 name=AHB_SLAVE_HIF

kworker/4:3-10711 [004] 1573.176150: sched_wakeup: comm=tx_thread pid=11483 prio=120 success=1 target_cpu=006 state=W

kworker/4:3-10711 [004] 1573.176152: irq_handler_exit: irq=270 ret=handled

// 생략

migration/1-11 [001] 1595.638701: irq_handler_entry: irq=232 name=ovl1_2l

migration/1-11 [001] 1595.638704: irq_handler_exit: irq=232 ret=handled

migration/1-11 [001] 1595.644768: irq_handler_entry: irq=30 name=arch_timer

// end of ftrace log

이제 더 watchdog reset의 원인을 더 좁히기 위해, 디버깅 정보를 좀 더 뒤져봐야 하는데요.

Uninterruptible 상태 프로세스 정보를 확인해볼께요. 보통 크래시 코어 덤프가 나오면 습관적으로 점검을 하곤 하거든요.

그런데 아래와 같이 평소에 보이지 않는 프로세스들이 보이네요.

crash> ps -l | grep UN

[1573221067182] [UN] PID: 1043 TASK: d8959000 CPU: 5 COMMAND: "android.io"

[1573169741644] [UN] PID: 273 TASK: dd903600 CPU: 5 COMMAND: "bat_update_thre"

[1573164748105] [UN] PID: 6531 TASK: c748a000 CPU: 5 COMMAND: "DnsConfigServic"

[1573163602413] [UN] PID: 4299 TASK: c1a8e600 CPU: 6 COMMAND: "DnsConfigServic"

[1573160763720] [UN] PID: 25 TASK: de900600 CPU: 4 COMMAND: "kworker/4:0"

[1573134929413] [UN] PID: 166 TASK: ddca8600 CPU: 4 COMMAND: "disp_idlemgr"

[1572444794180] [UN] PID: 172 TASK: dea1d000 CPU: 4 COMMAND: "disp_check"

[1571706203179] [UN] PID: 221 TASK: ddfc2600 CPU: 0 COMMAND: "touch_boost"

[ 67489120544] [UN] PID: 279 TASK: ddb81000 CPU: 5 COMMAND: "reclaim_task"

[ 61815993377] [UN] PID: 5447 TASK: c7464000 CPU: 5 COMMAND: "secwidevinemdw_"

[ 5302444704] [UN] PID: 483 TASK: da78d600 CPU: 4 COMMAND: "rpmb_Dci"

[ 1263689925] [UN] PID: 281 TASK: ddb83000 CPU: 1 COMMAND: "reset_task"

[ 695977770] [UN] PID: 168 TASK: de3d3000 CPU: 4 COMMAND: "decouple_trigge"

[ 680735924] [UN] PID: 165 TASK: ddc76000 CPU: 4 COMMAND: "ddp_irq_log_kth"

PID: 1043 TASK: d8959000 CPU: 5 COMMAND: "android.io" 프로세스 콜스택을 보니,

mutex lock을 획득하지 못해서 __schedule() 함수 호출로 sleep에 들어가네요.

-000|context_switch(inline)

-000|__schedule()

-001|schedule()

-002|schedule_preempt_disabled()

-003|spin_lock(inline)

-003|__mutex_lock_common(inline)

-003|__mutex_lock_slowpath(lock_count = 0xC0FBFB94)

-004|__mutex_fastpath_lock(inline)

-004|mutex_lock(lock = 0x0)

-005|rtnl_lock()

-006|devinet_ioctl(net = 0xC0FBEC40, ?, arg = 0x9BE1A20C)

-007|inet_ioctl(?, ?, ?)

-008|sock_do_ioctl(inline)

-008|sock_ioctl(?, cmd = 35093, ?)

-009|vfs_ioctl(inline)

-009|do_vfs_ioctl(filp = 0x0, ?, ?, ?)

-010|SYSC_ioctl(inline)

-010|sys_ioctl(fd = 267, cmd = 35093, arg = -1679711732)

-011|ret_fast_syscall(asm)

TASK: c748a000 CPU: 5 COMMAND: "DnsConfigServic" 프로세스도 마찬가지군요.

-000|context_switch(inline)

-000|__schedule()

-001|schedule()

-002|schedule_preempt_disabled()

-003|spin_lock(inline)

-003|__mutex_lock_common(inline)

-003|__mutex_lock_slowpath(lock_count = 0xC0FBFB94)

-004|__mutex_fastpath_lock(inline)

-004|mutex_lock(lock = 0x0)

-005|rtnl_lock()

-006|wireless_process_ioctl(inline)

-006|wext_ioctl_dispatch(inline)

-006|wext_handle_ioctl(net = 0xC0FBEC40, ifr = 0xC4EC5EA8, cmd = 35585, arg = 0x

-007|dev_ioctl(net = 0xC0FBEC40, cmd = 35585, arg = 0x9B73A4B4)

-008|sock_do_ioctl(inline)

-008|sock_ioctl(?, cmd = 35585, ?)

-009|vfs_ioctl(inline)

-009|do_vfs_ioctl(filp = 0x0, ?, ?, ?)

-010|SYSC_ioctl(inline)

-010|sys_ioctl(fd = 19, cmd = 35585, arg = -1686920012)

-011|ret_fast_syscall(asm)

위 두 프로세스에서 rtnl_lock() 함수 수행 후 __schedule() 함수 실행 중인 공통점을 확인할 수 있네요.

rtnl_lock() 함수 코드 리뷰 좀 해볼까요? rtnl_lock() 함수 body를 보니, rtnl_mutex란 mutex 변수로 락을 걸고 있음을 알 수 있어요.

void rtnl_lock(void)

{

mutex_lock(&rtnl_mutex);

// .. 생략..

rtnl_mutex 변수를 확인해보니 mutex lock owner가 "kworker/4:3"임을 알수 있어요.

mutex deadlock현상은 결국 문제의 원인이 아니라 결과임을 할 수 있어요.

(static struct mutex) rtnl_mutex = (

(atomic_t) count = ((int) counter = 0xFFFFFFFD),

(spinlock_t) wait_lock = ((struct raw_spinlock) rlock = ((arch_spinlock_t) r

(struct list_head) wait_list = (

(struct list_head *) next = 0xD91E5E04 -> (

(struct list_head *) next = 0xC4EC5E04 -> (

(struct list_head *) next = 0xD92E3E14 -> (

(struct list_head *) next = 0xC0FBFB9C -> (

(struct list_head *) next = 0xD91E5E04,

(struct list_head *) prev = 0xD92E3E14),

(struct list_head *) prev = 0xC4EC5E04),

(struct list_head *) prev = 0xD91E5E04),

(struct list_head *) prev = 0xC0FBFB9C),

(struct list_head *) prev = 0xD92E3E14),

(struct task_struct *) owner = 0xDA073600 -> (

(long int) state = 0x0,

(void *) stack = 0xC5728000,

// ..생략..

(struct cred *) cred = 0xD8FBD600,

(char [16]) comm = "kworker/4:3",

(int) link_count = 0x0,

그 이유는 "kworker/4:3" 프로세스가 rtnl_mutex 이란 mutex을 잠그고 __ipv6_dev_ac_inc() 함수에서 spinning으로 돌고 있었기 때문에, 다른 프로세스들이 rtnl_mutex란 mutex을 획득하지 못하는 상황이거든요.

-000|__ipv6_dev_ac_inc()

-001|addrconf_join_anycast()

-002|__ipv6_ifa_notify()

-003|local_bh_enable(inline)

-003|rcu_read_unlock_bh(inline)

-003|ipv6_ifa_notify()

-004|addrconf_dad_begin(inline)

-004|addrconf_dad_work()

-005|static_key_count(inline)

-005|static_key_false(inline)

-005|trace_workqueue_execute_end(inline)

-005|process_one_work()

-006|list_empty(inline)

-006|worker_thread()

-007|kthread()

-008|ret_from_fork(asm)

-009|ret_fast_syscall(asm)

그럼 "kworker/4:3" 프로세스가 rtnl_mutex란 mutex를 언제 거냐구요? 위 콜스택 정보를 참고하면 addrconf_dad_work 함수에서 rtnl_lock() 함수 호출로 rtnl_mutex란 mutex를 잠그고 있어요.

static void addrconf_dad_work(struct work_struct *w)

{

struct inet6_ifaddr *ifp = container_of(to_delayed_work(w),

struct inet6_ifaddr,

dad_work);

struct inet6_dev *idev = ifp->idev;

struct in6_addr mcaddr;

enum {

DAD_PROCESS,

DAD_BEGIN,

DAD_ABORT,

} action = DAD_PROCESS;

rtnl_lock();

그럼 __ipv6_dev_ac_inc() 함수로 되돌아갈 시간이네요.

__ipv6_dev_ac_inc() 함수를 리뷰해보면, 아래 for loop에서 함수가 계속 무한루프를 돌고 있었는데요.

int __ipv6_dev_ac_inc(struct inet6_dev *idev, const struct in6_addr *addr)

{

struct ifacaddr6 *aca;

struct rt6_info *rt;

int err;

// .. skip..

for (aca = idev->ac_list; aca; aca = aca->aca_next) {

if (ipv6_addr_equal(&aca->aca_addr, addr)) {

aca->aca_users++;

err = 0;

goto out;

}

idev->ac_list 변수가 어떤 값을 갖고 있는 지 점검을 해보았어요.

확인해보니 참 황당하게도 이 값이 0x0이네요.

(struct inet6_dev *) (struct inet6_dev *)0xC2000400 = 0xC2000400 -> (

(struct net_device *) dev = 0xDA5CA800,

(struct list_head) addr_list = ((struct list_head *) next = 0xD8C3CBC0, (str

// .. skip ..

(struct ifacaddr6 *) ac_list = 0x0,

kworker/4:3-10711란 프로세스가 __ipv6_dev_ac_inc() 함수 내 for loop를 돌면서 idev->ac_list 리스트를 iteration하는 동안에, 다른 모듈이 race condition으로 __ipv6_dev_ac_inc() 함수에 진입하여 idev->ac_list에 access한 것으로 보이네요.

아래와 같은 디버깅 패치를 작성해서 race condition이 발생하는지 점검하고 있었는데.

diff --git a/net/ipv6/anycast.c b/net/ipv6/anycast.c

index baf2742..44b28c0 100644

--- a/net/ipv6/anycast.c

+++ b/net/ipv6/anycast.c

@@ -257,6 +257,7 @@ int __ipv6_dev_ac_inc(struct inet6_dev *idev, const struct in6_addr *addr)

}

for (aca = idev->ac_list; aca; aca = aca->aca_next) {

+ trace_printk("%p caller: %pS\n", idev->ac_list, (void *)__builtin_return_address(0));

if (ipv6_addr_equal(&aca->aca_addr, addr)) {

aca->aca_users++;

err = 0;

네트워크 드라이버를 보는 분이 잽싸게 리눅스 커뮤니티에서 ipv6_ifa_notify() 함수가 race condition을 유발시킬 수 있다는 정보를 캐치하셨어요. 아래 패치 적용 후 문제가 재현되지 않았어요.

ipv6_ifa_notify() may need to acquire idev->lock, for example

when calling __ipv6_dev_ac_inc() from addrconf_join_anycast()

in __ipv6_ifa_notify().

So caller must release idev->lock before calling ipv6_ifa_notify() to

avoid a deadlock.

Fix a checkpatch warning present in the same area to make checkpatch

happy.

#패치 코드

diff --git a/net/ipv6/addrconf.c b/net/ipv6/addrconf.c

index 3d9afb7..7b92c50 100644

--- a/net/ipv6/addrconf.c

+++ b/net/ipv6/addrconf.c

@@ -2227,10 +2227,12 @@ static void manage_tempaddrs(struct inet6_dev *idev,

ift->flags &= ~IFA_F_DEPRECATED;

spin_unlock(&ift->lock);

- if (!(flags&IFA_F_TENTATIVE))

- ipv6_ifa_notify(0, ift);

- }

-

+ if (!(flags&IFA_F_TENTATIVE)) {

+ read_unlock_bh(&idev->lock);

+ ipv6_ifa_notify(0, ift);

+ read_lock_bh(&idev->lock);

+ }

if ((create || list_empty(&idev->tempaddr_list)) &&

idev->cnf.use_tempaddr > 0) {

/* When a new public address is created as described

@@ -3340,7 +3342,9 @@ static void addrconf_dad_begin(struct inet6_ifaddr *ifp)

/* Because optimistic nodes can use this address,

* notify listeners. If DAD fails, RTM_DELADDR is sent.

*/

- ipv6_ifa_notify(RTM_NEWADDR, ifp);

+ read_unlock_bh(&idev->lock);

+ ipv6_ifa_notify(RTM_NEWADDR, ifp);

+ read_lock_bh(&idev->lock);

}

"이 포스팅이 유익하다고 생각되시면 댓글로 응원해주시면 감사하겠습니다.

그리고 혹시 궁금점이 있으면 댓글로 질문 남겨주세요. 상세한 답글 올려드리겠습니다!"

# Reference: For more information on 'Linux Kernel';

디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 1

디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 2

'Core BSP 분석 > 커널 트러블슈팅' 카테고리의 다른 글

[Linux][Kernel] data abort@irq_affinity_notify - 리눅스 커널 (0)	2023.05.07
[Linux][Kernel] data abort @tty_wakeup - 리눅스 커널 (0)	2023.05.07
tombstone - __strlen_chk (0)	2023.05.07
Kernel][Panic] 메모리 불량 커널 크래시@find_vma_links - 1 (0)	2023.05.07
[Kernel][Panic] crash due to "signature and/or required key missing" (0)	2023.05.07

와치독 리셋이 발생하는 디바이스에서 아래와 같은 툼스톤, 즉 유언이 확인되었어요.

backtrace:

#00 pc 000221c8 /system/lib/libc.so (tgkill+12)

#01 pc 000131c9 /system/lib/libc.so (pthread_kill+48)

#02 pc 000133dd /system/lib/libc.so (raise+10)

#03 pc 00012113 /system/lib/libc.so

#04 pc 00021a7c /system/lib/libc.so (abort+4)

#05 pc 00012bf9 /system/lib/libc.so

#06 pc 00012c0f /system/lib/libc.so

#07 pc 00023af7 /system/lib/libc.so (__strlen_chk+18)

#08 pc 00000d27 /system/lib/libatd_mdminterface.so (request_to_mdm_via_port+382)

#09 pc 0001af4b /system/lib/libatd_common.so (request_to_system(int, char const*, int, char*, int*, int*)+254)

#10 pc 0001d033 /system/lib/libatd_common.so (read_pompeii_ntcode(char*, short, char*, int*)+26)

#11 pc 0001b92d /system/lib/libatd_common.so (get_pompeii_sw_version(int, char*, int*)+1588)

#12 pc 000158a9 /system/lib/libatd_common.so (system_write_version_info()+64)

#13 pc 00006a93 /system/bin/atd

#14 pc 0000d358 /system/lib/libc.so (__thread_entry+72)

#15 pc 0000d4f0 /system/lib/libc.so (pthread_create+240)

정확히 어디서 어보트가 발생하였는 지 확인하는게 중요한데요. 우선 아래 콜 스택을 점검해보았어요.

#07 pc 00023af7 /system/lib/libc.so (__strlen_chk+18)

#08 pc 00000d27 /system/lib/libatd_mdminterface.so (request_to_mdm_via_port+382) // 0x17E

바이너리 유틸리티를 사용해서 libatd_mdminterface.so를 파싱할 수 있는데요.

./arm-eabi-objdump -Sdl libatd_mdminterface.so > dump_atd_mdm.txt

request_to_mdm_via_port란 심볼의 가상 주소를 확인할 수 있어요. 00000ba8에서 0x17E만큼 주소를 더하면, 0xD26군요.

00000ba8 <request_to_mdm_via_port>:

request_to_mdm_via_port():

/src/android/vendor/atd/at_command_port.cpp:170 (discriminator 1)

d1c: f04f 0a00 mov.w sl, #0

strlen():

/src/android/bionic/libc/include/string.h:226 (discriminator 1)

d20: 4620 mov r0, r4

d22: f44f 7180 mov.w r1, #256 ; 0x100

d26: f7ff ed92 blx 84c <__strlen_chk@plt>

request_to_mdm_via_port():

정확히 170 라인에서 돌아가셨는데요.

138 int request_to_mdm_via_port(struct lgcmd_request *req, struct lgcmd_response *rsp)

139 {

140 int ret = -1;

141 int loop_count = 0;

142 char modem_atcmd_line[4096] = {0,};

...

170 if (write(fd_nv_port, (void *)mdm_atcmd_line, strlen(modem_atcmd_line)+1) <= 0) {

171 DEBUGMSG("[pompeii_interface] Write to modem port failed in request_to_mdm_via_port: %s\n", strerror(errno));

172 pthread_mutex_unlock(&mAtPortMut);

173

174 return -1;

175 }

죽기 전에 토해낸 디바이스의 다른 로그를 확인해 볼까요? 여기서 26으로 시작하는 엄청난 스트링이 어디서 찍히는 지 확인해보죠.

08-16 20:15:10.776 3858 3878 I Atd : [int request_to_mdm_via_port(lgcmd_request*, cmd_response*)] get atcmd line : AT%NTCODE?

08-16 20:15:10.776 3858 3878 I Atd : [int request_to_mdm_via_port(lgcmd_request*, cmd_response*)] read modem response, count : 1

08-16 20:15:10.785 3858 3878 I Atd : [request_to_mdm_via_port] response snippet:

"26","334,03F,FFFFFFFF,FFFFFFFF,FF","334,030,FFFFFFFF,FFFFFFFF,FF","704,03F,FFFFFFFF,FFFFFFFF,FF","704,030,FFFFFFFF,FFFFFFFF,FF","706,04F,FFFFFFFF,FFFFFFFF,FF","706,040,FFFFFFFF,FFFFFFFF,FF","710,30F,FFFFFFFF,FFFFFFFF,FF","710,300,FFFFFFFF,FFFFFFFF,FF","

tombstone에서 스택 주소 근처의 메모리 덤프를 볼 수 있는데, 이 값을 Trace32 시뮬레이터를 써서 올려볼 수 있어요.

아래 명령어로요.

D.S SD:0xC0001000 %LE %LONG 0xb67323d8 0x00000000 0x00000000 0x000f1ec9 0x00008000 0x00000000 0x00000000 0x00000000 0x00000006 0x0000006e 0x00000f26 0xb6e34fea 0xb6e34fea 0xb6eda1cd 0x00000006 0x00000000 0xb6ea3004 0xb6eda3e1 0xb6732424 0xb6ed9117 0x00000000 0xffffffdf 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0xb6f09cfb 0xb67336d8 0xb6ee8a80 0x4fc7b724 0xb6ed9bfd 0xb6f07927 0xb6732464 0x01000000 0xb6ed9c13 0xb6f07927 0xb6f09cfb 0x01000000 0x4e255400 0x00000100 0xb6eeaafb 0xb673249c 0xb6e34d2b 0xb6e3538f 0xb673249c 0x00000000 0xb6f16384 0xb6e35230 0xb6e353c0 0x00000000 0x32220a0d 0x222c2236 0x2c343333 0x2c463330 0x46464646 0x46464646 0x4646462c 0x46464646 0x46462c46 0x33222c22 0x302c3433 0x462c3033 0x46464646

그러면 아래와 같이 스택 공간에 로딩되어 있는 헥사값을 확인할 수 있어요.

_______0________4________8________C_0123456789ABCDEF

B67323D8 00000000 00000000 000F1EC9 .#s.............

00008000 00000000 00000000 00000000 ................

00000006 0000006E 00000F26 B6E34FEA ....n...&....O..

B6E34FEA B6EDA1CD 00000006 00000000 .O..............

B6EA3004 B6EDA3E1 B6732424 B6ED9117 .0......$$s.....

00000000 FFFFFFDF 00000000 00000000 ................

00000000 00000000 00000000 B6F09CFB ................

B67336D8 B6EE8A80 4FC7B724 B6ED9BFD .6s.....$..O....

B6F07927 B6732464 01000000 B6ED9C13 'y..d$s.........

B6F07927 B6F09CFB 01000000 4E255400 'y...........T%N

00000100 B6EEAAFB B673249C B6E34D2B .........$s.+M..

B6E3538F B673249C 00000000 B6F16384 .S...$s......c..

B6E35230 B6E353C0 00000000 32220A0D 0R...S........"2

222C2236 2C343333 2C463330 46464646 6","334,03F,FFFF

46464646 4646462C 46464646 46462C46 FFFF,FFFFFFFF,FF

33222C22 302C3433 462C3033 46464646 ","334,030,FFFFF

해당 담당자에게 위 정보를 공유했더나 바로 코드 수정을 해서 문제는 사라졌어요.

물론 코드 정보를 알려주지 않았는데 스트링을 쪼개서 전달했나봐요.

'Core BSP 분석 > 커널 트러블슈팅' 카테고리의 다른 글

[Linux][Kernel] data abort @tty_wakeup - 리눅스 커널 (0)	2023.05.07
watchdog reset - race in ipv6_ifa_notify() - 리눅스 커널 (0)	2023.05.07
Kernel][Panic] 메모리 불량 커널 크래시@find_vma_links - 1 (0)	2023.05.07
[Kernel][Panic] crash due to "signature and/or required key missing" (0)	2023.05.07
[Linux][Kernel]뮤텍스 데드락(Mutex Deadlock) 락업(lockup) - "simpleperf" 디버깅 (0)	2023.05.07

#커널 크래시 디버깅 및 TroubleShooting

특정 디바이스가 부팅 후 5분 이내에 커널 패닉이 발생하는 현상을 리포트 받았는데요.

참 신기하죠? 특정 디바이스만 커널 패닉이라.

이럴 때 너무 긴장할 필요 없어요. 논리적인 오류로 발생한 커널 패닉인지 정확히 분석한 후,

논리적인 문제가 아니라면 하드웨어 담당자에게 메모리 불량이 아닌 지 테스트(보통 정상 메모리와 스왑하죠)을 요청하면 되요.

커널 패닉 시 로그는 아래와 같아요.

CPU5에서 돌던 find_vma_links() 함수의 find_vma_links+0x1c 코드에서 데이터 오버트가(Data Abort) 발생했네요. 프로세스 이름은 "sensorservice" 이구요.

[ 2107.239317 / 01-01 11:11:03.809][5] Unable to handle kernel NULL pointer dereference at virtual address 00000028

[ 2107.239351 / 01-01 11:11:03.809][5] pgd = e37ec000

[ 2107.239366 / 01-01 11:11:03.809][0] [00000028] *pgd=00000000

[ 2107.239388 / 01-01 11:11:03.809][5] Internal error: Oops: 5 [#1] PREEMPT SMP ARM

[ 2107.239405 / 01-01 11:11:03.809][0] Modules linked in: texfat(PO)

[ 2107.239433 / 01-01 11:11:03.809][5] CPU: 5 PID: 2803 Comm: sensorservice Tainted: P W O 3.18.31-perf-gd069b48-00001-g8a6d6e5 #1

[ 2107.239452 / 01-01 11:11:03.809][5] task: e3ffb700 ti: e37f4000 task.ti: e37f4000

[ 2107.239479 / 01-01 11:11:03.809][5] PC is at find_vma_links+0x1c/0x78

[ 2107.239499 / 01-01 11:11:03.809][5] LR is at vma_adjust+0x3a0/0x574

find_vma_links() 함수를 잠깐 보면 struct task_struct->mm에 위치한 메모리 디스크립터를 통해

특정 조건으로 &mm->mm_rb.rb_node rbtree를 검색하는 루틴으로 보이는데요.

static int find_vma_links(struct mm_struct *mm, unsigned long addr,

unsigned long end, struct vm_area_struct **pprev,

struct rb_node ***rb_link, struct rb_node **rb_parent)

{

struct rb_node **__rb_link, *__rb_parent, *rb_prev;

__rb_link = &mm->mm_rb.rb_node; //<<--

우선 crash-utility(crash too)로 콜스택을 잡아 봤어요.

crash> bt -I C01002D8 -S E37F5DD0 0xE3FFB700

PID: 2803 TASK: e3ffb700 CPU: 5 COMMAND: "sensorservice"

#0 [<c01002d8>] (do_DataAbort) from [<c010ad58>]

pc : [<c01f980c>] lr : [<c01fa708>] psr: 200f0013

sp : e37f5ec4 ip : 00000034 fp : e8236d9c

r10: 00000000 r9 : 00000000 r8 : b2c99000

r7 : c4616c80 r6 : e8236d68 r5 : 7f555034 r4 : 7f555034

r3 : e37f5f04 r2 : b2c97000 r1 : b2c95000 r0 : 7f555038

Flags: nzCv IRQs on FIQs on Mode SVC_32 ISA ARM

#1 [<c010ad58>] (__dabt_svc) from [<c01fa708>]

#2 [<c01f980c>] (find_vma_links) from [<c01fa708>]

#3 [<c01fa708>] (vma_adjust) from [<c01fa9e4>]

#4 [<c01fa9e4>] (__split_vma) from [<c01fb364>]

#5 [<c01fb364>] (do_munmap) from [<c01fb558>]

#6 [<c01fb558>] (vm_munmap) from [<c0106820>]

그럼 Data Abort가 어떻게 일어났는지 좀 더 세밀하게 디버깅해볼까요?

Data Abort가 발생한 코드가 0xc01f980c이고 해당 Instrution이 "ldr r0, [r12, #-12]" 이네요.

즉 R12에서 -0xC 만큼 떨어진 메모리에 위치한 값을 로딩하다가 Data Abort가 발생했네요.

이 때, Data Abort가 발생할 시점에 R12가 0x34이거든요. (ip : 00000034)

이럴 때는 R12 레지스터을 좀 더 세밀하게 트레이싱할 필요가 있어요. 어떻게 R12값이 바뀌었는지 점검해야 하는 거죠.

[1]: R0가 0x7f555038이구요. 0x7f555038 메모리 공간에 있는 값이 0x34이니 R12는 0x34가 되네요.

[2]: ARM 프로세스가 "ldr r0, [r12, #-12]" 명령어를 수행하기 위해 ldr의 Base Address인 R12에 접근하다가,

Data Abort를 발생시켰어요. 왜냐면요, ldr란 명령어를 수행할 때 반드시 MMU이 개입하는데, 0x34란 주소는

MMU Page table에 없는 주소거든요. 도대체 global page directory에 접근할 수 없는 쓰레기 주소라 판단하여 Data abort를 유발시키는 거죠.

0xc01f97f0 <find_vma_links>: push {r4, r5, lr}

0xc01f97f4 <find_vma_links+0x4>: add r0, r0, #4

0xc01f97f8 <find_vma_links+0x8>: mov r4, #0

0xc01f97fc <find_vma_links+0xc>: mov r5, r4

0xc01f9800 <find_vma_links+0x10>: ldr r12, [r0] //<<--[1]

0xc01f9804 <find_vma_links+0x14>: cmp r12, #0

0xc01f9808 <find_vma_links+0x18>: beq 0xc01f983c <find_vma_links+76>

0xc01f980c <find_vma_links+0x1c>: ldr r0, [r12, #-12] //<<--[2]

커널 패닉이 발생한 C 코드와 함께 비교하면서 분석해볼까요?

[1]: 코드에서 Data abort가 발생한 건데요, 이 코드를 어셈블 코드와 비교해볼께요.

static int find_vma_links(struct mm_struct *mm, unsigned long addr,

unsigned long end, struct vm_area_struct **pprev,

struct rb_node ***rb_link, struct rb_node **rb_parent)

{

struct rb_node **__rb_link, *__rb_parent, *rb_prev;

__rb_link = &mm->mm_rb.rb_node; //<<--[1]

&mm->mm_rb.rb_node이 코드를 어셈블 코드에서 어떻게 돌아가는 지 점검하면요.

1> &mm->mm_rb.rb_node

이 포인터 연산을 위해서 우선 &mm->mm_rb 주소에 접근을 해야 하거든요.

이 동작을 아래 명령어에서 수행하죠.

0xc01f97f4 <find_vma_links+0x4>: add r0, r0, #4

struct mm_struct 구조체를 살펴보면 아래와 같이, 0x4 오프셋만큼 떨어진 멤버 변수가 mm_rb이거든요.

그래서 "add r0, r0, #4" 명령어에서 0x4만큼 더하는 거에요.

struct mm_struct {

[0x0] struct vm_area_struct *mmap;

[0x4] struct rb_root mm_rb;

2> &mm->mm_rb.rb_node

R0가 &mm->mm_rb 주소를 가르키고 있으니 이제 rb_node 주소에 접근하네요.

0xc01f9800 <find_vma_links+0x10>: ldr r12, [r0]

&mm->mm_rb 타입이 struct rb_root이구 이 구조체의 0x0 오프셋 멤버가 rb_node이라 위 명령어가 수행된 거랍니다.

crash> struct -o rb_root

struct rb_root {

[0x0] struct rb_node *rb_node;

}

그런데, find_vma_links() 함수의 선언부는 보면 첫 번째 파라미터가 "struct mm_struct *mm"이거든요.

이 소리는 find_vma_links() 함수가 호출될 때 R0에 "struct mm_struct *mm" 주소를 전달했다는 건데요.

static int find_vma_links(struct mm_struct *mm, unsigned long addr,

unsigned long end, struct vm_area_struct **pprev,

struct rb_node ***rb_link, struct rb_node **rb_parent)

코드 리뷰를 좀 해보면, find_vma_links() 함수의 첫 번째 파라미터로 전달되는 "struct mm_struct *mm"는

해당 프로세스의 struct task_struct.mm 멤버임을 알 수 있구요.

커널 패닉이 발생한 프로세스의 task descriptor(struct task_struct)의 주소가 e3ffb700이니,

"struct mm_struct *mm"은 0xc4616d80 주소가 되어야 하네요.

crash> struct task_struct.mm e3ffb700

mm = 0xc4616d80

이 값을 Trace32로 올려서 주소 오프셋값 까지 함께 살펴보니 아래와 같네요. 다들 정상적인 값을 갖고 있어요..

v.v %t %l (struct mm_struct*)0xc4616d80

(struct mm_struct *) [-] (struct mm_struct*)0xc4616d80 = 0xC4616D80 -> (

(struct vm_area_struct *) [D:0xC4616D80] mmap = 0xE6FB7E18,

(struct rb_root) [D:0xC4616D84] mm_rb = (

(struct rb_node *) [D:0xC4616D84] rb_node = 0xE7D259B0),

(u32) [D:0xC4616D88] vmacache_seqnum = 22,

정리하면, Data Abort가 발생한 이유는 R0가 0xC4616D84(0xC4616D80+0x4) 대신 0x7f555038값이기 때문이구요. 구지 Trace32로 문제 발생 시의 레지스터를 표현하면 아래와 같아요. 정말 이상하죠?

v.v %t %l (struct mm_struct*)0xc4616d80

(struct mm_struct *) [-] (struct mm_struct*)0xc4616d80 = 0xC4616D80 -> (

(struct vm_area_struct *) [D:0xC4616D80] mmap = 0xE6FB7E18,

(struct rb_root) [D:0x7f555038] mm_rb = (

(struct rb_node *) [D:0x7f555038] rb_node = 0x34),

(u32) [D:0xC4616D88] vmacache_seqnum = 22,

SW 로직 문제로 보이는 문제가 보이지 않아서, HW팀에게 메모리 점검을 요청했더니

메모리 스왑 후 커널 크래시가 발생하지 않았다고 하네요.

역시, 끝은 허무하네요.

# Reference: For more information on 'Linux Kernel';

디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 1

디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 2

출처: https://askubuntu.com/questions/773734/how-to-install-module-ko-module-without-kernel-signature-or-kernel-rebuild-in-ub

'Core BSP 분석 > 커널 트러블슈팅' 카테고리의 다른 글

watchdog reset - race in ipv6_ifa_notify() - 리눅스 커널 (0)	2023.05.07
tombstone - __strlen_chk (0)	2023.05.07
[Kernel][Panic] crash due to "signature and/or required key missing" (0)	2023.05.07
[Linux][Kernel]뮤텍스 데드락(Mutex Deadlock) 락업(lockup) - "simpleperf" 디버깅 (0)	2023.05.07
[Linux][Kernel] Kernel Panic @__stack_chk_fail - 스택 카나리 (Stack canary Feature) (0)	2023.05.07

#커널 크래시 디버깅 및 TroubleShooting

Built-in 타입 디바이스 드라이버 모듈을 적재하는 과정에서 커널 크래시가 발생했는데요.

개고생 하다가 결국 밝혀낸 것이 디바이스 드라이버 모듈의 signed build관련한 문제였어요.

이틀인가, 야근을 한 것 같은데. 그리 많이 공유할만한 자료가 없다는게 좀 더 허무하네요.

비슷한 문제를 겪는 분들은 아래 내용 참고하셔서 저 같이 쓸때없는 야근을 하시지 않길 바래요.

아래 콜스택으로 커널 패닉이 발생했는데요. 0xBF03B114란 주소에서 문제가 발생했는데.

0xBF03B114이면 드라이버 모듈 코드에서 커널 패닉이 일어났다는 것을 확인할 수 있죠.

-000|do_DataAbort(?)

-001|__dabt_svc(asm)

-->|exception

-002|NSR:0xBF03B114(asm) // <<--

-003|do_one_initcall_debug(inline)

-003|do_one_initcall(fn = 0xBF03B000)

-004|do_init_module(inline)

-004|load_module(info = 0xDE895F48, ?, ?)

-005|sys_init_module(umod = -1227014136, len = 284732, uargs = -1097475832)

-006|ret_fast_syscall(asm)

역시나 커널 패닉 발생 직전 아래 커널이 아래 로그를 토해내고 있네요. 뭐가 문제일까요?

[ 6.886562] <c2> (6)[1:init]init: processing action 0x141078 (post-fs)

[ 6.904338] <86> (2)[1:init]texfat: module license 'Commercial. For support email exfat-support@tuxera.com' taints kernel.

[ 6.904365] <86> (2)[1:init]Disabling lock debugging due to kernel taint

[ 6.904892] <a6> (2)[1:init][name:module&]texfat: module verification failed: signature and/or required key missing - tainting kernel

[ 6.908088] <e6> (2)[1:init]calling init_exfat_fs+0x0/0x2f0 [texfat] @ 1

코드 리뷰를 해보니 세상에,

CONFIG_MODULE_SIG_FORCE 란 config가 빠져 있었네요.

비슷한 이슈가 예전 프로젝트에서도 리포트된 것 같은데요

[Documentation/module-signing.txt]

(1) "Require modules to be validly signed" (CONFIG_MODULE_SIG_FORCE)

This specifies how the kernel should deal with a module that has a

signature for which the key is not known or a module that is unsigned.

If this is off (ie. "permissive"), then modules for which the key is not

available and modules that are unsigned are permitted, but the kernel will

be marked as being tainted, and the concerned modules will be marked as

tainted, shown with the character 'E'.

If this is on (ie. "restrictive"), only modules that have a valid

signature that can be verified by a public key in the kernel's possession

will be loaded. All other modules will generate an error.

Irrespective of the setting here, if the module has a signature block that

cannot be parsed, it will be rejected out of hand.

texfat란 드라이버 모듈은 제가 signed 빌드할 때 build 키를 쓰지 않고 빌드했을 꺼잖아요.

따라서 signing 안된 드라이버 모듈을 로딩을 하려고 하니 커널이 위 에러 로그를 토해내는 거구요.

제대로 signing된 디바이스 드라이버 모듈만 verification시키는 CONFIG_MODULE_SIG_FORCE 컨피그를 추가하니 문제가 사라졌어요.

"이 포스팅이 유익하다고 생각되시면 댓글로 응원해주시면 감사하겠습니다.

그리고 혹시 궁금점이 있으면 댓글로 질문 남겨주세요. 상세한 답글 올려드리겠습니다!"

# Reference: For more information on 'Linux Kernel';

디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 1

디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 2

- ARM64 - 각 익셉션(Exception) 레벨 소개

'Core BSP 분석 > 커널 트러블슈팅' 카테고리의 다른 글

tombstone - __strlen_chk (0)	2023.05.07
Kernel][Panic] 메모리 불량 커널 크래시@find_vma_links - 1 (0)	2023.05.07
[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

#커널 크래시 디버깅 및 TroubleShooting

특정 시점부터 갑자기 디바이스가 락업되는 현상이 리포트가 되었거든요. 엄청 락업된 디바이스가 쏟아 졌었는데요.

이번 시간에는 그 때 어떻게 디버깅을 해서 문제를 해결했는지 업데이트하고자 해요.

락업이 된 상태에서 디바이스를 받아 강제로 코어 덤프를 뜬 다음에 콜 트레이스를 봤는데요.

아래 콜 스택이 확인되었어요. 프로세스 이름은 "atd" 이에요.

reboot 시스템콜을 trigger한 다음에 각 종 시스템 드라이버를 종료하는 과정에서 mutex lock을 계속 기다리는 현상이 확인되네요.

-000|context_switch(inline)

-000|__schedule()

-001|schedule_preempt_disabled()

-002|spin_lock(inline)

-002|__mutex_lock_common(inline)

-002|__mutex_lock_slowpath(lock_count = 0xC1327164)

-003|current_thread_info(inline)

-003|mutex_set_owner(inline)

-003|mutex_lock(lock = 0xC1327164) // cpu_add_remove_lock

-004|cpu_hotplug_disable()

-005|migrate_to_reboot_cpu()

-006|kernel_restart(cmd = 0x0)

-007|SYSC_reboot(inline)

-007|sys_reboot(magic1 = -18751827, ?, cmd = 19088743, arg = 0)

-008|ret_fast_syscall(asm)

-->|exception

-009|__reboot(asm) // android/bionic/libc/arch-arm/syscalls/__reboot.S|9

-010|restart(?)

-011|__pthread_start(arg = 0xB55F7930)

-012|__start_thread(?, ?)

뮤텍스 데드락 현상이 의심되네요. 어떤 프로세스가 뮤텍스 락을 잡고 나서 실행 도중 잠들어버려 다른 프로세스가

그 뮤텍스 락을 못잡는 시나리오를 생각해볼 수 있는데요.

뮤텍스 락을 잡고 슬립에 빠지거나 뮤텍스 락을 기다리리며 잠들어 있는 프로세스들은 Interrupt을 받으면 안되기 때문에, 프로세스 상태가 Uninterruptible 상태(struct task_struct->state = TASK_UNINTERRUPTIBLE)이거든요.

이럴 때 "ps -l | grep UN" 명령어를 입력하면 Uninterruptbile 상태 프로세스를 확인할 수 있어요.

흠, 그런데 "simpleperf" 프로세스가 보이네요.

crash> ps -l | grep UN

[33341014778844] [UN] PID: 16965 TASK: c3362f40 CPU: 0 COMMAND: "atd" // <<--

[ 3069103232273] [UN] PID: 8919 TASK: d4bfb9c0 CPU: 0 COMMAND: "simpleperf" // <<--

[ 727796356] [UN] PID: 123 TASK: df6e9500 CPU: 1 COMMAND: "mdss_dsi_event"

"simpleperf" 프로세스(PID: 8919)의 콜스택을 살펴보니, 뮤텍스 락을 잡고 잠들어버리고 있네요.

세부 디버깅 정보는 콜 스택 옆에 있는 주석문을 참고하세요.

-00 |context_switch(inline)

-00 |__schedule()

-01 |schedule_preempt_disabled()

-02 |spin_lock(inline)

-02 |__mutex_lock_common(inline)

-02 |__mutex_lock_slowpath(lock_count = 0xDD05A008)

-03 |current_thread_info(inline)

-03 |mutex_set_owner(inline)

-03 |mutex_lock(lock = 0xDD05A008) // <<-- mutex lock

-04 |SYSC_perf_event_open(inline) // /data/misc/perfprofd/perferr.txt 파일을 오픈

-04 |sys_perf_event_open(?, pid = 3, cpu = 0, ?, flags = 0)

-05 |ret_fast_syscall(asm)

--> |exception

-06 |syscall(asm) // <<-- userspace system calls

-07 |perf_event_open(inline)

-07 |EventFd::OpenEventFile(?, pid = 8919, cpu = -1) // <<-- android/system/extras/simpleperf/event_fd.cpp|37

-08 |EventFd::OpenEventFileForProcess(attr = (typ //<<-- android/system/extras/simpleperf/event_fd.cpp|41

-09 |operator bool(inline)

-09 |operator!=<EventFd, std::__1::default_delete<EventFd> >(inline)

-09 |IsEventTypeSupportedByKernel(inline)

-09 |IsSupportedByKernel(inline)

-09 |EventTypeFactory::FindEventTypeByName(?, ?)

-10 |SetMeasuredEventType(inline)

-10 |RecordCommandImpl::Run(this = 0xBEB08848, ?)

-11 |RecordCommand::Run(?, args = (std::__1::__vector_base<std::__1::basic_strin

-12 |main(?, ?)

-13 |__libc_init(?, ?, slingshot = 0xB6F9AB45, ?)

-14 |start(asm)

mutex_lock(lock = 0xDD05A008)에서 보이는 mutex lock 디버깅 좀 해볼께요.

뮤텍스 락을 획득하기 위해 기다리는 프로세스는 struct mutex->wait_list 리스트에 자신의 뮤텍스(Mutex) 인스턴스를 등록하고 잠들어거든요.

(struct mutex*)0xDD05A008 = 0xDD05A008 -> (

count = (counter = 0xFFFFFFFF),

wait_lock = (rlock = (raw_lock = (slock = 0x00010001, tickets = (owner = 0x1

wait_list = (

next = 0xD1611EBC -> (

next = 0xDD05A010,

prev = 0xDD05A010),

prev = 0xD1611EBC),

owner = 0xD4BFB9C0, // <<-- "simpleperf", PID: 8919 프로세스의 task descriptor

spin_mlock = 0x0)

container_of(출처: http://rousalome.egloos.com/9963702) 란 매크로를 써서 뮤텍스 락을 디버깅을 좀 더 해봤더니, "simpleperf" 란 프로세스가 뮤덱스 락을 한번 획득하고 난 다음에 또 다시 획득하려다가 잠들어 버린 디버깅 정보가 확인되네요.

wait_list.next=0xD1611EBC

(struct mutex *) container_of(0xD1611EBC,struct mutex,wait_list) = 0xD1611EB4

// snip

(struct task_struct *) owner = 0xD4BFB9C0 //<<--"simpleperf", PID: 8919 프로세스의 task descriptor

wait_list.next.next=0xDD05A010

(struct mutex *) container_of(0xDD05A010,struct mutex,wait_list) = 0xDD05A008

(atomic_t) count = ((int) counter = -1 = 0xFFFFFFFF = '....'),

//snip

(struct task_struct *) owner = 0xD4BFB9C0 // <<-- "simpleperf", PID: 8919 프로세스의 task descriptor

코드 리뷰를 해보니 정말로 mutex lock을 두 번 잡고 있네요.

어떤 분이 커널 마이그레이션을 하다가 conflict이 나서 실수로 mutex lock 코드를 추가한 것 같아요.

SYSCALL_DEFINE5(perf_event_open,

struct perf_event_attr __user *, attr_uptr,

pid_t, pid, int, cpu, int, group_fd, unsigned long, flags)

{

// .. 생략..

if (move_group) {

gctx = group_leader->ctx;

/*

* See perf_event_ctx_lock() for comments on the details

* of swizzling perf_event::ctx.

*/

mutex_lock_double(&gctx->mutex, &ctx->mutex);

perf_remove_from_context(group_leader, false);

perf_event__state_init(group_leader);

list_for_each_entry(sibling, &group_leader->sibling_list,

group_entry) {

perf_remove_from_context(sibling, false);

perf_event__state_init(sibling);

put_ctx(gctx);

}

} else {

mutex_lock(&ctx->mutex); //<<--

}

WARN_ON_ONCE(ctx->parent_ctx);

mutex_lock(&ctx->mutex); //<<-

위에 보이는 mutex_lock을 삭제하니 문제는 사라졌어요. 커널 마이그레이션 할 때 conflict나면 살 떨려서 어떻게 하죠? 조심해야 겠어요.

# Reference (ARM Processor)

- [T32] Cortex A53: 프로세스 별 Call Stack 복원하는 방법

- ARM32- 스택 푸쉬(Stack Push) Userspace -> Kernel Space

- ARM64- 스택 푸쉬(Stack Push) Userspace -> Kernel Space

- ARM64(Aarch64) - Special Register 설정(Trace32)

- ARM64 - Data Abort Exception(익셉션) Vector 실행

- arm32 - Unwind Idx/prolog 소개

- [Linux][ARM] Coprocessor(코프로세서) Assembly

# Reference: For more information on 'Linux Kernel';

디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 1

디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 2