'Core BSP 분석/커널 트러블슈팅' 카테고리의 글 목록 (3 Page)

Core BSP 분석/커널 트러블슈팅

tombstone - __strlen_chk 2023.05.07
Kernel][Panic] 메모리 불량 커널 크래시@find_vma_links - 1 2023.05.07
[Kernel][Panic] crash due to "signature and/or required key missing" 2023.05.07
[Linux][Kernel]뮤텍스 데드락(Mutex Deadlock) 락업(lockup) - "simpleperf" 디버깅 2023.05.07
[Linux][Kernel] Kernel Panic @__stack_chk_fail - 스택 카나리 (Stack canary Feature) 2023.05.07
[Linux][Kernel] panic@___might_sleep 2023.05.07
[Linux][Kernel][Stability] Kernel panic @0x0 from xfrm_local_error+0x4c 2023.05.07
[Kernel][Debug] "cat /d/shrinker" kernel panic 2023.05.07
[Linux-Kernel][Debug]kernel panic@mmc_wait_data_done 2023.05.07

tombstone - __strlen_chk

AustinKim 2023. 5. 7. 17:51

2023. 5. 7. 17:51

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

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

Kernel][Panic] 메모리 불량 커널 크래시@find_vma_links - 1

AustinKim 2023. 5. 7. 17:50

2023. 5. 7. 17:50

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

http://www.yes24.com/Product/Goods/90085976

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

http://www.yes24.com/Product/Goods/90087307

저작자표시

'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

[Kernel][Panic] crash due to "signature and/or required key missing"

AustinKim 2023. 5. 7. 17:48

2023. 5. 7. 17:48

#커널 크래시 디버깅 및 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가 빠져 있었네요.

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

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

[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

http://www.yes24.com/Product/Goods/90085976

https://wikibook.co.kr/linux-kernel-1/

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

http://www.yes24.com/Product/Goods/90087307

https://wikibook.co.kr/linux-kernel-2/

저작자표시

'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

[Linux][Kernel]뮤텍스 데드락(Mutex Deadlock) 락업(lockup) - "simpleperf" 디버깅

AustinKim 2023. 5. 7. 17:47

2023. 5. 7. 17:47

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

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

- [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

http://www.yes24.com/Product/Goods/90085976

https://wikibook.co.kr/linux-kernel-1/

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

http://www.yes24.com/Product/Goods/90087307

https://wikibook.co.kr/linux-kernel-2/

저작자표시

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

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] 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] Kernel Panic @__stack_chk_fail - 스택 카나리 (Stack canary Feature)

AustinKim 2023. 5. 7. 17:46

2023. 5. 7. 17:46

#커널 크래시 디버깅 및 TroubleShooting

최근 흥미로운 커널 패닉이 나왔는데요. 디버깅 과정을 공유 좀 하고자 해요.

일단 콜스택부터 볼께요. sock_has_perm() 함수가 돌다가 갑자기 __stack_chk_fail() 함수 호출로 panic()이 일어났거든요. 왜 이런 현상이 발생했을까요?

crash> bt e5752c00

PID: 1787 TASK: e5752c00 CPU: 4 COMMAND: "net_socket"

bt: WARNING: stack address:0xe853fa38, program counter:0xc0ee5b60

#0 [<c0ed8b64>] (panic) from [<c0125038>]

#1 [<c0125038>] (__stack_chk_fail) from [<c032b6cc>]

#2 [<c032b6cc>] (sock_has_perm) from [<c0327d00>]

#3 [<c0327d00>] (security_socket_recvmsg) from [<c0ceb1c8>]

#4 [<c0ceb1c8>] (sock_recvmsg) from [<c0cec474>]

#5 [<c0cec474>] (___sys_recvmsg) from [<c0ced5b4>]

#6 [<c0ced5b4>] (__sys_recvmsg) from [<c0106820>]

Trace32로 콜스택을 잡으면 아래 정보를 확인할 수 있습니다. 커널 패닉이 발생한 흔적이 보이죠.

-000|panic(fmt = 0xC1379761)

-001|__stack_chk_fail()

-002|sock_has_perm(?, sk = 0xE98D3400, perms = 2)

-003|security_socket_recvmsg(?, ?, ?, ?)

-004|__sock_recvmsg(inline)

-004|sock_recvmsg(sock = 0xC3C99C00, msg = 0xE853FF7C, size = 65536, flags = 0)

-005|___sys_recvmsg.part.5(sock = 0xC3C99C00, msg = 0xA08813B0, msg_sys = 0xE853FF7C, flags = 0, nosec = 0)

-006|fput_light(inline)

-006|__sys_recvmsg(?, msg = 0xA08813B0, flags = 0)

-007|ret_fast_syscall(asm)

T32(Trace32)로 UP 버튼으로 security_socket_recvmsg() 함수가 호출될 시점 스택 주소를 확인하면, 0xE853FDD8 임을 알 수 있습니다.

-003|security_socket_recvmsg(?, ?, ?, ?)

-004|__sock_recvmsg(inline)

-004|sock_recvmsg(sock = 0xC3C99C00, msg = 0xE853FF7C, size = 65536, flags = 0)

-005|___sys_recvmsg.part.5(sock = 0xC3C99C00, msg = 0xA08813B0, msg_sys = 0xE853FF7C, flags = 0, nosec =

-006|fput_light(inline)

-006|__sys_recvmsg(?, msg = 0xA08813B0, flags = 0)

-007|ret_fast_syscall(asm)

N _ R0 C1379761 R8 E5752C00

Z _ R1 E853FD54 R9 0

C _ R2 DC8CB01F R10 C3C99C00

V _ R3 0 R11 0

Q _ R4 C3C99C00 R12 0

R5 00010000 R13 E853FDD8

0 _ R6 E853FF7C R14 0

1 _ R7 0 PC C0327D00

2 _ SPSR 10 CPSR 01D3

"d.v %y.l 0xE853FDD8" 명령어로 스택에 푸쉬된 심볼을 확인할 수 있습니다.

NSD:E853FD4C| 38 50 12 C0 0xC0125038 \\vmlinux\panic\__stack_chk_fail+0x10

NSD:E853FD50| 61 97 37 C1 0xC1379761 \\vmlinux\Global\kallsyms_token_index+0x5D41

NSD:E853FD54| CC B6 32 C0 0xC032B6CC \\vmlinux\hooks\sock_has_perm+0x9C

NSD:E853FD58| 1F B0 8C DC 0xDC8CB01F

NSD:E853FD5C| 00 00 00 00 0x0

NSD:E853FD60| 00 00 00 00 0x0

NSD:E853FD64| CC B6 32 C0 0xC032B6CC \\vmlinux\hooks\sock_has_perm+0x9C

NSD:E853FD68| 74 FD 53 E8 0xE853FD74

NSD:E853FD6C| A0 FD 53 E8 0xE853FDA0

NSD:E853FD70| 7C FF 53 E8 0xE853FF7C

NSD:E853FD74| 02 05 00 00 0x502 \\vmlinux\Global\NR_syscalls+0x37E

NSD:E853FD78| 84 FD 53 E8 0xE853FD84

NSD:E853FD7C| C4 04 D4 C0 0xC0D404C4 \\vmlinux\af_netlink\netlink_recvmsg\out+0x38

NSD:E853FD80| 70 08 FD EC 0xECFD0870

NSD:E853FD84| 00 00 00 00 0x0

NSD:E853FD88| 00 34 8D E9 0xE98D3400

NSD:E853FD8C| 00 00 00 00 0x0

NSD:E853FD90| 00 00 00 00 0x0

NSD:E853FD94| 00 00 00 00 0x0

NSD:E853FD98| 00 00 00 00 0x0

NSD:E853FD9C| 00 00 00 00 0x0

NSD:E853FDA0| 00 00 00 00 0x0

NSD:E853FDA4| 00 00 00 00 0x0

NSD:E853FDA8| 00 00 00 00 0x0

NSD:E853FDAC| 00 00 00 00 0x0

NSD:E853FDB0| 00 00 00 00 0x0

NSD:E853FDB4| 1F B0 8C DC 0xDC8CB01F

NSD:E853FDB8| 00 0A 82 ED 0xED820A00 // E853FDBC - 0x54 = 0xE853FD68 "where: sub r13,r13,#0x54 ; r13,r13,#84"

NSD:E853FDBC| 00 9C C9 C3 0xC3C99C00 //<<-- R4

NSD:E853FDC0| 00 00 01 00 0x10000 //<<-- R5

NSD:E853FDC4| 7C FF 53 E8 0xE853FF7C //<<-- R6

NSD:E853FDC8| 00 00 00 00 0x0 //<<-- R7

NSD:E853FDCC| 00 2C 75 E5 0xE5752C00 //<<-- R8

NSD:E853FDD0| 00 00 00 00 0x0 //<<-- R9

NSD:E853FDD4| 00 7D 32 C0 0xC0327D00 \\vmlinux\security\security_socket_recvmsg+0x14 //<<-- R14

NSD:E853FDD8| 00 00 00 00 0x0 //<<-- 스택 주소

NSD:E853FDDC| C8 B1 CE C0 0xC0CEB1C8 \\vmlinux\socket\sock_recvmsg+0x58

security_socket_recvmsg 함수에서 sock_has_perm 함수 호출 시 0x54 바이트 만큼 스택을 잡습니다.

NSR:C032B630|E92D43F0 sock_has_perm: push {r4-r9,r14}

NSR:C032B634|E24DD054 sub r13,r13,#0x54 ; r13,r13,#84

이제 코드 리뷰를 좀 해보겠습니다.

[1]: sock_has_perm() 함수가 처음 security_socket_recvmsg() 함수로부터 호출되었을 때 스택 주소는 0xE853FDD8이네요.

[2]: 스택이 푸쉬된 다음에 스택 주소는 0xE853FDBC로 업데이트 되었네요.

Stack: 0xE853FDBC(0xE853FDD8-0x1C)

[3]: 로컬 변수들은 스택 메모리에서 돌죠. 로컬 변수가 스택을 쓸 수 있도록 0x54 바이트 만큼 방을 비워줍니다.

Stack: 0xE853FD68(0xE853FDBC-0x54)

[4]: R7는 0xC1809948 을 갖고 있는데 여기서 __stack_chk_guard란 함수를 링크하네요.

c032b6d4: c1809948 .word 0xc1809948

crash> p &__stack_chk_guard

$3 = (unsigned long *) 0xc1809948 <__stack_chk_guard>.

[5]: R3는 stack canary 매직값 0xdc8cb01f을 갖고 있는데 이런 계산으로 R3 = 0xdc8cb01f = *0xC1809948 업데이트되네요.

아래 명령어를 치면 0xC1809948 주소에 dc8cb01f란 값이 위치해 있어요.

.crash> rd 0xC1809948

c1809948: dc8cb01f

[6]: Stack canary 매직 덤프값 0xdc8cb01f이 스택으로 푸쉬되고 있네요. R3이 갖고 있는 값을 스택에 푸쉬하는 거죠. 0xE853FDB4 주소로 푸쉬되죠.

0xE853FDB4=0xE853FD68+0x4c = SP+0x4c

[7]: [6]번 인스트럭션에서 stack canary magic dump 값을 스택(0xE853FD68+0x4c = SP+0x4c) 공간에 푸쉬했잖아요.

똑같은 메모리 공간에 접근해서 stack canary magic dump 값을 꺼내와요. 이 값 0xdc8cb01f은 R2에 업데이트되죠.

[8]: 여기서 중요한 점은 [6] 명령어가 실행된 다음에 R7 레지스터는 변경된 적이 없다는 점인데요.

R7 레지스터가 0xC1809948 값을 갖고 있어야 하는데 0xC1800048 값이네요.

그래서 R3이 갑자기 0x0으로 바뀌어 있어요.

원래 R7 레지스터가 0xC1809948를 갖고 있으면 당연히 R3은 0xdc8cb01f일텐데 말이죠.

0xc032b638 <sock_has_perm+8>: ldr r7, [pc, #148]

[9]: R2과 R3값이 다르니 커널 패닉이 발생하네요. kernel panic occurs

#Code

0xc032b630 <sock_has_perm>: push {r4, r5, r6, r7, r8, r9, lr} //<<--[2]

0xc032b634 <sock_has_perm+0x4>: sub sp, sp, #84 ; 0x54 //<<--[3]

0xc032b638 <sock_has_perm+0x8>: ldr r7, [pc, #148] ; 0xc032b6d4 <sock_has_perm+0xa4> //<<--[4]

0xc032b63c <sock_has_perm+0xc>: add r6, sp, #28

0xc032b640 <sock_has_perm+0x10>: mov r9, r0

0xc032b644 <sock_has_perm+0x14>: ldr r4, [r1, #420] ; 0x1a4

0xc032b648 <sock_has_perm+0x18>: mov r5, r1

0xc032b64c <sock_has_perm+0x1c>: mov r8, r2

0xc032b650 <sock_has_perm+0x20>: ldr r3, [r7] //<<--[5]

0xc032b654 <sock_has_perm+36>: mov r1, #0

0xc032b658 <sock_has_perm+40>: mov r2, #48 ; 0x30

0xc032b65c <sock_has_perm+44>: mov r0, r6

0xc032b660 <sock_has_perm+48>: str r3, [sp, #76] ; 0x4c //<<--[6]

// snip

0xc032b6b8 <sock_has_perm+0x88>: ldr r2, [sp, #76] ; 0x4c //<<--[7]

0xc032b6bc <sock_has_perm+0x8c>: ldr r3, [r7] //<<--[8]

0xc032b6c0 <sock_has_perm+0x90>: cmp r2, r3

0xc032b6c4 <sock_has_perm+0x94>: beq 0xc032b6cc <sock_has_perm+156>

0xc032b6c8 <sock_has_perm+0x98>: bl 0xc0125028 <__stack_chk_fail> //<<--[9]

좀 어렵게 설명한 것 같은데요. 쉽게 C코드로 변경하면 아래와 같아요.

void sock_has_perm(void)

{

int stack_check = &__stack_chk_guard;

int loc_stack = 0;

loc_stack = stack_check;

// 여러 서브 함수들이 호출됨. 각 함수가 호출이 일어날 때 마다 당연 스택 푸쉬/팝 동작이 수행됨

A();

B();

C();

D();

loc_stack값과 stack_check값이 다르다는 것은 스택이 오염되었다고 판단하므로, 커널 패닉 유발!

if (loc_stack != stack_check) {

__stack_chk_fail();

}

0xdc8cb01f은 R2로 업데이트되는데요. "ldr r2, [sp, #76] ; 0x4c"

만약 스택이 오염되었으면 R2가 이상한 값을 갖고 있어야 하는데, 이번 경우는 R3이 이상한 값을 갖고 있어서 커널 패닉이 발생한 거거든요.

이 이슈의 핵심 포인트는 R7 레지스터가 0xC1809948 값을 갖고 있어야 하는데 0xC1800048 값이라는 거구요.

붉은 색으로 책한 공간에 비트 플립이 일어나 발생한 문제 -> 0xC1800048(0xC1809948)로 확인되었어요.

사실 이 디바이스 상태가 좀 안 좋았거든요. 그래서 메모리를 바꾸어서 테스트 해 보았더니 별 문제 없더라구요.

스택 카너리에 대해 좀 더 설명을 하면요. boot_init_stack_canary() 함수에서 스택 카너리를 초기화합니다. 참고로 이 함수는 start_kernel()에서 호출됩니다. 아래 코드를 잠깐 보면 task descriptor(TCB)의 멤버에 stack_canary에 canary 값을 초기화합니다.

extern unsigned long __stack_chk_guard;

static __always_inline void boot_init_stack_canary(void)

{

unsigned long canary;

/* Try to get a semi random initial value. */

get_random_bytes(&canary, sizeof(canary));

canary ^= LINUX_VERSION_CODE;

current->stack_canary = canary;

__stack_chk_guard = current->stack_canary;

}

658 ifdef CONFIG_CC_STACKPROTECTOR_REGULAR

659 stackp-flag := -fstack-protector

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

661 $(warning Cannot use CONFIG_CC_STACKPROTECTOR_REGULAR: \

662 -fstack-protector not supported by compiler)

663 endif

이 플래그를 설정하면, 리눅스 커널에서 기본으로 호출되는 여러 함수들 하단에 __stack_chk_fail 스택 오염 진단 루틴을 추가합니다.

0xc0100974 <do_one_initcall+404>: bl 0xc0125028 <__stack_chk_fail>

0xc0100d8c <name_to_dev_t+828>: bl 0xc0125028 <__stack_chk_fail>

0xc0107854 <__show_regs+700>: bl 0xc0125028 <__stack_chk_fail>

0xc01219c0 <sha384_neon_final+108>: bl 0xc0125028 <__stack_chk_fail>

0xc0133c34 <sys_newuname+352>: bl 0xc0125028 <__stack_chk_fail>

0xc0133d68 <sys_sethostname+276>: bl 0xc0125028 <__stack_chk_fail>

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

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

http://www.yes24.com/Product/Goods/90085976

https://wikibook.co.kr/linux-kernel-1/

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

http://www.yes24.com/Product/Goods/90087307

https://wikibook.co.kr/linux-kernel-2/

저작자표시

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

[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] panic@___might_sleep (0)	2023.05.07
[Linux][Kernel][Stability] Kernel panic @0x0 from xfrm_local_error+0x4c (0)	2023.05.07
[Kernel][Debug] "cat /d/shrinker" kernel panic (0)	2023.05.07

[Linux][Kernel] panic@___might_sleep

AustinKim 2023. 5. 7. 17:45

2023. 5. 7. 17:45

#커널 크래시 디버깅 및 TroubleShooting

리눅스 커널 synchronization의 꽃 중의 하나인 Mutex Lock에 대해서 조금 짚어 볼께요. Mutex Lock은 보통 스핀락(Spinlock)과 많이 비교하죠. 사실 소스 코드를 보면 Mutex Lock이 스핀락보다 훨씬 소프트웨어적으로 복잡해요. 그 이유는?

1> Mutex Lock을 잠근 프로세스만 해제할 수 있어요

2> 이미 다른 프로세스가 Mutex Lock을 획득한 상태면 struct mutex.wait_list에 대기하고 Wait Queue에 넣고

잠들어야 해요.

음, 이 소리는. Mutex Lock을 잡고 있는 프로세스가 Mutex Lock을 해제하면 누군가가 다시 대기 중이던 프로세스를 WaitQueue에서 끄집어 내서 런큐에 큐잉을 해줘야겠죠.

마지막으로 Mutex Lock을 잡는 동작에서 Sanity-Check을 해주는 루틴이 있어요. 이 역할을 하는 함수가 ___might_sleep()이거든요. 함수의 구현부는 아래와 같은데요. 아래 if문 3개의 조건을 만족하면 return되는데, return이 안되면 커널 크래시가 기다리고 있어요.

void ___might_sleep(const char *file, int line, int preempt_offset)

{

static unsigned long prev_jiffy; /* ratelimiting */

unsigned long preempt_disable_ip;

rcu_sleep_check(); /* WARN_ON_ONCE() by default, no rate limit reqd. */

if ((preempt_count_equals(preempt_offset) && !irqs_disabled() && //<<--

!is_idle_task(current)) || oops_in_progress)

return;

if (system_state != SYSTEM_RUNNING &&

(!__might_sleep_init_called || system_state != SYSTEM_BOOTING))

return;

if (time_before(jiffies, prev_jiffy + HZ) && prev_jiffy)

return;

prev_jiffy = jiffies;

/* Save this before calling printk(), since that will clobber it */

preempt_disable_ip = get_preempt_disable_ip(current);

printk(KERN_ERR

"BUG: sleeping function called from invalid context at %s:%d\n",

file, line);

printk(KERN_ERR

"in_atomic(): %d, irqs_disabled(): %d, pid: %d, name: %s\n",

in_atomic(), irqs_disabled(),

current->pid, current->comm);

//snip

#ifdef CONFIG_PANIC_ON_SCHED_BUG

BUG(); //<←

그런데 위 코드에서 커널 패닉이 죽는 덤프를 봤거든요.

콜스택은 아래와 같구요. Binder 드라이버에서 Mutex Lock을 잡는 동작에서 커널 크래시가 발생한 거네요.

-000|do_debug_exception(addr = 0, esr = 0, regs = 0x0)

-001|el1_dbg(asm)

-->|exception

-002|___might_sleep(file = 0xFFFFFF8BA9C4C2F3, ?, ?) //<<-- panic

-003|__might_sleep(file = 0xFFFFFF8BA9C4C2F3, line = 98, preempt_offset = 0)

-004|mutex_lock(lock = 0xFFFFFFCCF32FC938)

-005|binder_defer_work(proc = 0xFFFFFFCCE000FC80, ?)

-006|binder_flush(filp = 0xFFFFFFCC998D8300, ?)

-007|filp_close(filp = 0xFFFFFFCC998D8300, id = 0xFFFFFFCD472DBAC0)

-008|__close_fd(files = 0xFFFFFFCD472DBAC0, ?)

-009|task_close_fd.isra.33(?)

-010|binder_transaction_buffer_release(proc = 0xFFFFFFCD46098480, buffer = 0xFFFFFF801F12D270, failed_at

-011|binder_transaction(?, thread = 0xFFFFFFCCE000EC80, tr = 0xFFFFFFCCA944BC30, ?, extra_buffers_size =

-012|binder_thread_write(proc = 0xFFFFFFCCE000FC80, thread = 0xFFFFFFCCE000EC80, ?, ?, consumed = 0xFFFFF

-013|binder_ioctl_write_read(filp = 0xFFFFFFCC998D8300, ?, arg = 549020159624, thread = 0xFFFFFFCCE000EC8

-014|binder_ioctl(filp = 0xFFFFFFCC998D8300, cmd = 3224396289, arg = 549020159624)

-015|vfs_ioctl(inline)

-015|do_vfs_ioctl(filp = 0xFFFFFFCC998D8300, fd = 1, ?, arg = 549020159624)

-016|SYSC_ioctl(inline)

-016|sys_ioctl(fd = 1, cmd = 3224396289, arg = 549020159624)

커널 패닉이 발생한 이유는 해당 프로세스의 struct thread_info의 preempt_count값이 2이기 때문이죠.

(struct thread_info*)(0xffffffcca944b880 & ~0x3fff) = 0xFFFFFFCCA9448000 -> (

flags = 0x2,

addr_limit = 0x0000008000000000,

task = 0xFFFFFFCD03CC1FC0,

ttbr0 = 0x44510000BB944000,

preempt_count = 0x2, //<<--

cpu = 0x6)

다시 말하자면, preempt_disable() 함수를 두 번 호출했다는 거죠.

preempt_disable()의 구현부를 보면, 간단히 struct thread_info.preempt_count 값만 +1시키고 있어요.

#define preempt_disable() \

do { \

preempt_count_inc(); \

barrier(); \

} while (0)

사실 이 값 struct thread_info.preempt_count이 0이어야만 preemption이 되어 스케쥴이 가능하거든요. 그 이유는 다른 섹션에서 다루기로 하구요. (어셈블코드 리뷰가 필요할 것 같네요.)

아무리 눈을 씻고 찾아봐도, 그리 논리적 오류가 될만한 코드가 없어 보여서,

아래와 같은 패치를 반영했더니, 크래시는 사라졌어요.

원리는 잠시 preempt_count를 -1 시켜서 _mutex_sleep에서 크래시를 회피하고 이후,

다시 원래 값으로 돌리는 거죠.

diff --git a/drivers/android/binder.c b/drivers/android/binder.c

index d1490be..eea603b 100644

--- a/drivers/android/binder.c

+++ b/drivers/android/binder.c

@@ -458,7 +458,9 @@ static long task_close_fd(struct binder_proc *proc, unsigned int fd)

if (proc->files == NULL)

return -ESRCH;

+ preempt_enable_no_resched();

retval = __close_fd(proc->files, fd);

+ preempt_disable();

/* can't restart close syscall because file table entry was cleared */

if (unlikely(retval == -ERESTARTSYS ||

retval == -ERESTARTNOINTR ||

관련 매크로는 아래 코드를 참고하세요.

#define preempt_enable_no_resched() sched_preempt_enable_no_resched()

#define sched_preempt_enable_no_resched() \

do { \

barrier(); \

preempt_count_dec(); \

} while (0)

#define __preempt_count_dec() __preempt_count_sub(1)

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

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

http://www.yes24.com/Product/Goods/90085976

https://wikibook.co.kr/linux-kernel-1/

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

http://www.yes24.com/Product/Goods/90087307

https://wikibook.co.kr/linux-kernel-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][Stability] Kernel panic @0x0 from xfrm_local_error+0x4c (0)	2023.05.07
[Kernel][Debug] "cat /d/shrinker" kernel panic (0)	2023.05.07
[Linux-Kernel][Debug]kernel panic@mmc_wait_data_done (0)	2023.05.07

[Linux][Kernel][Stability] Kernel panic @0x0 from xfrm_local_error+0x4c

AustinKim 2023. 5. 7. 17:44

2023. 5. 7. 17:44

#커널 크래시 디버깅 및 TroubleShooting

커널 패닉이 났어요.

네트워크 드라이버 리눅스 커널 코드에서 발생한 것 같은데요. 음.

일단 당황하지 마시구요. 차근 차근 커널 로그와 코어 덤프를 살펴보면, 정답이 나와요.

일단 커널 로그를 보면, 프로그램 카운터가 0x0을 가르키고 있네요.

음... 그리고

링크 레지스터(R14)가 0xc0adc274(LR is at xfrm_local_error+0x4c/0x58) 을 가르키고 있습니다.

[ 262.401303] Unable to handle kernel NULL pointer dereference at virtual address 00000000

[ 262.401365] pgd = dbdc4000

[ 262.401389] [00000000] *pgd=00000000

[ 262.401433] Internal error: Oops: 80000005 [#1] PREEMPT SMP ARM

[ 262.401459] Modules linked in:

[ 262.401495] CPU: 0 PID: 7107 Comm: Framework Tainted: G W 3.10.49-g356bd9f-00007-gadca646 #1

[ 262.401522] task: da6b0540 ti: d9412000 task.ti: d9412000

[ 262.401549] PC is at 0x0

[ 262.401590] LR is at xfrm_local_error+0x4c/0x58

[ 262.401619] pc : [<00000000>] lr : [<c0adc274>] psr: a00f0013

[ 262.401619] sp : d9413c68 ip : c0ac6c20 fp : 0000dd86

[ 262.401654] r10: 0000010e r9 : 0000010a r8 : de0ddc20

[ 262.401678] r7 : c13ddf00 r6 : 00000500 r5 : d9094540 r4 : c13e3780

[ 262.401703] r3 : 00000000 r2 : 00000001 r1 : 00000500 r0 : d9094540

일단 커널 로그에서 R14가 가르키는(커널 패닉이 발생한 함수를 호출한) 주소로 가보면요.

R3를 branch instruction으로 수행하고 있었습니다. 이런 Instruction은 함수 포인터로 함수를 호출할 때 쓰이죠.

그런데 커널 로그에서 R3이 0x0이라고 하네요.

NSR:C0ADC264|E1A00005 cpy r0,r5 ; proto,skb

NSR:C0ADC268|E594344C ldr r3,[r4,#0x44C]

NSR:C0ADC26C|E1A01006 cpy r1,r6 ; r1,mtu

NSR:C0ADC270|E12FFF33 blx r3 //<<--

아 이제, 커널 로그가 가르키는 스택 주소 0xd9413c68로 좀 가볼까요?

d.v %y.l 0xD9413C68

______address|_data________|value_____________|symbol

NSD:D9413C60| 13 00 0F A0 0xA00F0013

NSD:D9413C64| FF FF FF FF 0xFFFFFFFF

NSD:D9413C68| 40 45 09 D9 0xD9094540 // <<-R4

NSD:D9413C6C| 00 0C 42 DC 0xDC420C00 //<<--R5

NSD:D9413C70| 40 45 09 D9 0xD9094540 //<<-- R6

NSD:D9413C74| 0C 11 AD C0 0xC0AD110C \vmlinuxxfrm4_output__xfrm4_output+0xE4 //<<--R14

NSD:D9413C78| 00 00 00 00 0x0

NSD:D9413C7C| 01 00 00 00 0x1

NSD:D9413C80| 00 0C 42 DC 0xDC420C00

NSD:D9413C84| 6C C0 AD C0 0xC0ADC06C \vmlinuxxfrm_outputxfrm_output_resume+0x41C

@D9413C74 스택 주소를 보니, 0xC0AD110C 즉 __xfrm4_output+0xE4 주소를 볼 수 있는데요.

0xC0AD110C 주소를 가보니, xfrm_local_error란 함수를 branch operation으로 수행을 하네요.

______addr/line|code_____|label____|mnemonic________________|comment

NSR:C0AD1104|E1A00004 cpy r0,r4 ; r0,skb

NSR:C0AD1108|EB002C46 bl 0xC0ADC228 ; xfrm_local_error

xfrm_local_error() 함수 초반 ARM Instruction을 보면, R14, R6, R5, R4 순으로 스택에 Push를 하네요.

NSR:C0ADC228|E92D4070 xfrm_local_error: push {r4-r6,r14}

NSR:C0ADC22C|E1A05000 cpy r5,r0 ; skb,pr

예를 들면, 이런 거죠. 스택에 이렇게 Push를 하고나면 새로운 스택 주소는 D9413C68(<-D9413C74)가 되는거죠.

stack 주소

D9413C68 R4을 스택에 Push =>> 0xD9094540

D9413C6C R5을 스택에 Push =>> 0xDC420C00

D9413C70 R6을 스택에 Push =>> 0xD9094540

D9413C74 R14 주소 스택에 Push =>> 0xC0AD110C

이렇게 새로운 함수가 호출될 때 스택에 파라미터를 Push하는 규칙은 CPU 아키텍쳐마다 다르거든요.

위의 경우에는 ARM32 아키텍처 Calling Convention에 따른 거에요.

ARM 스팩 문서를 보시면 위 내용이 자세히 나와 있어요.

자 다시 커널 로그로 돌아가 봅시다.

[ 262.401495] CPU: 0 PID: 7107 Comm: BaldTainted: G W 3.10.49-g356bd9f-00007-gadca646 #1

[ 262.401522] task: da6b0540 ti: d9412000 task.ti: d9412000

[ 262.401549] PC is at 0x0

[ 262.401590] LR is at xfrm_local_error+0x4c/0x58

[ 262.401619] pc : [<00000000>] lr : [<c0adc274>] psr: a00f0013

[ 262.401619] sp : d9413c68 ip : c0ac6c20 fp : 0000dd86

T32 프로그램으로,

커널 로그에서 찍힌 LR을 프로그램 카운터로 설정하고, 스택 주소는 그대로 설정 그리고 위 스택 정보에서 살펴본 0xC0AD110C(__xfrm4_output+0xE4) 주소를

설정하면. 이렇게 이쁘게 콜 스택이 보이네요.

-000|xfrm_local_error(skb = 0xDCD376C0, mtu = -611987776)

-001|__xfrm4_output(skb = 0xD9094540)

-002|xfrm_output_resume(skb = 0xD9094540, err = 1)

-003|__xfrm4_output(skb = 0xD9094540)

-004|ip_local_out(skb = 0xD9094540)

-005|ip_send_skb(net = 0xC13DDF00, ?)

-006|udp_send_skb(skb = 0xD9094540, ?)

-007|udp_sendmsg(?, sk = 0xDE0F1680, msg = 0xD9413EE0, len = 1300)

-008|inet_sendmsg(iocb = 0xD9413E58, ?, msg = 0xD9413EE0, size = 1300)

-009|sock_sendmsg(sock = 0xDA9A5500, msg = 0xD9413EE0, size = 1300)

-010|SYSC_sendto(inline)

-010|sys_sendto(?, buff = -1997588480, ?, ?, addr = -1985806992, addr_len = 16)

-011|ret_fast_syscall(asm)

T32 명령어는 아래와 같아요.

r.s R13 0xD9413C68

r.s R14 0xC0AD110C

r.s PC 0xC0ADC270

0xC0ADC270 주소에 다시 가볼까요? R3가 어떻게 0x0으로 업데이트되는지 봐야겠죠.

확인해보니, ldr r3,[r4,#0x44C] 명령어로 업데이트 되네요.

NSR:C0ADC264|E1A00005 cpy r0,r5 ; proto,skb

NSR:C0ADC268|E594344C ldr r3,[r4,#0x44C]

NSR:C0ADC26C|E1A01006 cpy r1,r6 ; r1,mtu

NSR:C0ADC270|E12FFF33 blx r3

0xC0ADC270 주소로 실제 소스 코드 위치를 알면 좋을 상황인데요. T32에서 이런 상황에서 아주 유용한 커맨드를 제공해요.

y.l.line 0xC0ADC270

__________address________|module__________________________________|source________|line______|o

P:C0ADC25C--C0ADC263|\vmlinuxxfrm_output |.1/android/kernel/net/xfrm/xfrm_output.c|247--247 |

P:C0ADC264--C0ADC273|\vmlinuxxfrm_output |.1/android/kernel/net/xfrm/xfrm_output.c|248--250 |

음, kernel/net/xfrm/xfrm_output.c의 248--250 라인인 것 같네요.

역시나, 실제 소스 코드를 보면 함수 포인터(콜백 함수 형태)로 함수를 호출하고 있네요.

234void xfrm_local_error(struct sk_buff *skb, int mtu)

235{

236 unsigned int proto;

237 struct xfrm_state_afinfo *afinfo;

238

// ...생략...

245

246 afinfo = xfrm_state_get_afinfo(proto);

247 if (!afinfo)

248 return;

249

250 afinfo->local_error(skb, mtu); //<<--

251 xfrm_state_put_afinfo(afinfo);

struct xfrm_state_afinfo란 구조체에서 local_error란 멤버의 오프셋 주소가 얼마인지 알아볼까요?

예를 들어서, bald_manager란 구조체가 있으면, issue 멤버는 0x4, issue_list 멤버는 0x8 오프셋이라고 볼 수 있어요.

struct bald_manager {

int phone;

int issue;

struct list_head issue_list;

};

음, 이럴 때 커널 패닉을 디버깅하는 Crash Tool이란 좋은 툴에서 아주 유용한 기능을 제공하거든요.

아래와 같은 명령어를 입력하면, local_error 멤버의 오프셋이 0x44c임을 알 수 있어요.

crash> struct -o xfrm_state_afinfo.local_error

struct xfrm_state_afinfo {

[0x44c] void (*local_error)(struct sk_buff *, u32);

}

어떤 T32 매니아가 저에게 질문을 던지네요.

음 T32로는 확인할 수 없냐구요? 아래 매크로 기능으로 확인 가능해요.

T32로 아래 명령어를 입력하면 되요.

sYmbol.NEW.MACRO offsetof(type,member) ((int)(&((type*)0)->member))

이게 제가 뚝딱만든 코드는 아니구요. 이미 리눅스 커널 코드에 있는 매크로를 그대로 가져온 거거든요.

[android/kernel/include/linux/stddef.h]

#define offsetof(TYPE, MEMBER) ((size_t) &((TYPE *)0)->MEMBER)

요렇게 입력하면 똑같은 0x044C 오프셋 주소를 확인할 수 있어요. T32로 디버깅할 때 자주 쓰면 좋아요.

v.v %h offsetof(struct xfrm_state_afinfo,local_error)

offsetof(struct xfrm_state_afinfo,local_error) = 0x044C

자, 이제 0xC0ADC270 주소에 다시 가보면 [1] instruction이 afinfo->local_error(skb, mtu); 함수 라인에 매핑되는 걸 알 수 있어요.

NSR:C0ADC264|E1A00005 cpy r0,r5 ; proto,skb

NSR:C0ADC268|E594344C ldr r3,[r4,#0x44C] //<<--[1]

250 afinfo->local_error(skb, mtu); //<<--[1]

NSR:C0ADC26C|E1A01006 cpy r1,r6 ; r1,mtu

NSR:C0ADC270|E12FFF33 blx r3

커널 패닉 시 로그를 다시 보면, R4가 0xc13e3780이거든요.

이 값을 T32로 (struct xfrm_state_afinfo *) 타입으로 캐스팅해서 올려보면, local_error값이 0x0이네요.

어라, 그리고 0xC13E3780 주소의 정체가 xfrm4_state_afinfo란 전역 벼수라는 것도 알 수 있네요.

v.v %all (struct xfrm_state_afinfo *)0xc13e3780

(struct xfrm_state_afinfo *) (struct xfrm_state_afinfo *)0xc13e3780 = 0xC13E3780 = xfrm4_state_afinfo -> (

(unsigned int) family = 2 = 0x2 = '....',

(unsigned int) proto = 4 = 0x4 = '....',

(__be16) eth_proto = 8 = 0x8 = '..',

(struct module *) owner = 0x0 = -> NULL,

(struct xfrm_type * [256]) type_map = ([0] = 0x0 = -> NULL, [1] = 0x0 = -> NULL, [2] = 0x0 = -> NULL, [3] = 0

(struct xfrm_mode * [5]) mode_map = ([0] = 0xC13E31D8 = xfrm4_transport_mode -> ((int (*)()) input2 = 0x0 = , (i

(int (*)()) init_flags = 0xC0AD0AD0 = xfrm4_init_flags -> ,

(void (*)()) init_tempsel = 0xC0AD0B6C = __xfrm4_init_tempsel -> ,

(void (*)()) init_temprop = 0xC0AD0AF4 = xfrm4_init_temprop -> ,

(int (*)()) tmpl_sort = 0x0 = -> NULL,

(int (*)()) state_sort = 0x0 = -> NULL,

(int (*)()) output = 0xC0AD12E4 = xfrm4_output -> ,

(int (*)()) output_finish = 0xC0AD129C = xfrm4_output_finish -> ,

(int (*)()) extract_input = 0xC0AD0D8C = xfrm4_extract_input -> ,

(int (*)()) extract_output = 0xC0AD11E0 = xfrm4_extract_output -> ,

(int (*)()) transport_finish = 0xC0AD0D94 = xfrm4_transport_finish -> ,

(void (*)()) local_error = 0x0 = -> NULL) //<<--

이제 정리 좀 하면.

afinfo->local_error(skb, mtu); 주소가 0x0이라서 커널 패닉으로 타겟이 크래시가 난 거에요.

참, 결론은 허무하죠. 대부분의 커널 패닉 문제는 허무하게 끝납니다.

아 이제, 코드 리뷰를 해볼 시간인데. xfrm4_state_afinfo란 변수 선언문을 가보았더니 에서 local_error 멤버를 초기화하지 않고 있네요.

[kernel/net/ipv4/xfrm4_state.c]

static struct xfrm_state_afinfo xfrm4_state_afinfo = {

.family = AF_INET,

.proto = IPPROTO_IPIP,

.eth_proto = htons(ETH_P_IP),

.owner = THIS_MODULE,

.init_flags = xfrm4_init_flags,

.init_tempsel = __xfrm4_init_tempsel,

.init_temprop = xfrm4_init_temprop,

.output = xfrm4_output,

.output_finish = xfrm4_output_finish,

.extract_input = xfrm4_extract_input,

.extract_output = xfrm4_extract_output,

.transport_finish = xfrm4_transport_finish,

};

아래와 같이 local_error 멤버에 대한 콜백 함수를 추가하는 코드를 추가하니 커널 패닉 증상은 사라졌습니다.

diff --git a/net/ipv4/xfrm4_state.c b/net/ipv4/xfrm4_state.c

index 9258e75..0b2a064 100644

--- a/net/ipv4/xfrm4_state.c

+++ b/net/ipv4/xfrm4_state.c

@@ -83,6 +83,7 @@ static struct xfrm_state_afinfo xfrm4_state_afinfo = {

.extract_input = xfrm4_extract_input,

.extract_output = xfrm4_extract_output,

.transport_finish = xfrm4_transport_finish,

+ .local_error = xfrm4_local_error,

};

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

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

http://www.yes24.com/Product/Goods/90085976

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

http://www.yes24.com/Product/Goods/90087307

저작자표시

'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
[Kernel][Debug] "cat /d/shrinker" kernel panic (0)	2023.05.07
[Linux-Kernel][Debug]kernel panic@mmc_wait_data_done (0)	2023.05.07

[Kernel][Debug] "cat /d/shrinker" kernel panic

AustinKim 2023. 5. 7. 17:42

2023. 5. 7. 17:42

#커널 크래시 디버깅 및 TroubleShooting

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]; <<--

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할 수 있었는데 아쉽네요.

https://chromium-review.googlesource.com/c/345895/

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

http://www.yes24.com/Product/Goods/90085976

https://wikibook.co.kr/linux-kernel-1/

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

http://www.yes24.com/Product/Goods/90087307

https://wikibook.co.kr/linux-kernel-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

[Linux-Kernel][Debug]kernel panic@mmc_wait_data_done

AustinKim 2023. 5. 7. 17:41

2023. 5. 7. 17:41

#커널 크래시 디버깅 및 TroubleShooting

Debugging

"ndroid.systemui" 프로세스가 raw_spin_lock_irqsave() API 동작 중에 watchdog reset이 되었다.

-000|aee_wdt_atf_entry()

-001|prefetchw(inline)

-001|arch_spin_lock(inline)

-001|do_raw_spin_lock_flags(inline)

-001|__raw_spin_lock_irqsave(inline)

-001|raw_spin_lock_irqsave(lock = 0xDD82725C)

-002|__wake_up(q = 0xDD82725C, mode = 1, nr_exclusive = 1, key = 0x0)

-003|mmc_wait_data_done

-004|msdc_irq_data_complete(host = 0xDD827280, ?, error = 0)

-005|msdc_irq(?, dev_id = 0xDD13B9C8)

-006|static_key_count(inline)

-006|static_key_false(inline)

-006|trace_irq_handler_exit(inline)

-006|handle_irq_event_percpu(?, action = 0xDD13B9C8)

-007|handle_irq_event(desc = 0xC0F38440)

-008|cond_unmask_eoi_irq(inline)

-008|handle_fasteoi_irq(?, desc = 0xC0F38440)

-009|static_key_count(inline)

-009|static_key_false(inline)

-009|trace_irq_exit(inline)

-009|__handle_domain_irq(domain = 0xDE806000, hwirq = 111, lookup = TRUE, ?)

-010|__raw_readl(inline)

-010|gic_handle_irq(regs = 0xDD13BFB0)

-011|__irq_usr(asm)

spinlock이 release되어 spinlock 변수가 [owner: 0x56AC, next: 0x56AD]로 업데이트되기까지 기다리고 있었다.

다른 프로세스가 spinlock을 잡고 있었는데..

(raw_spinlock_t *)0xDD82725C = 0xDD82725C -> (

raw_lock = (

slock = 0x56AD56AB,

tickets = (

owner = 0x56AB, // <<--

next = 0x56AD))) // <<--

0xDD82725C spinlock 변수 주소를 누가 접근하는 지 검색해보면.

(where)

(raw_spinlock_t *)0xDD82725C

c2d01b78: dd82725c

c2d01b7c: dd82725c

c44f0994: dd82725c

dd13bd60: dd82725c // "ndroid.systemui"

dd13bd9c: dd82725c // "ndroid.systemui"

dd13bdc8: dd82725c // "ndroid.systemui"

ddbefdb8: dd82725c // <<--"mmcqd/0"

ddbefdd0: dd82725c

e0abd994: dd82725c

"mmcqd/0" 프로세스가 접근함을 알 수 있었다.

v.v % (struct thread_info*)(0xDDBEFDB8 & ~0x1fff)

(long unsigned int) swap_in = 0 = 0x0 = '....',

(long unsigned int) swap_out = 0 = 0x0 = '....',

(struct task_cputime) cputime_expires = ((cputime_t) utime = 0 = 0x0 = '....', (cputime_t) stime = 0 = 0x0 = '....', (long lo

(struct list_head [3]) cpu_timers = ([0] = ((struct list_head *) next = 0xDDB49A08 = -> ((struct list_head *) next = 0xDDB49

(struct cred *) real_cred = 0xDDB71200 = -> ((atomic_t) usage = ((int) counter = 2 = 0x2 = '....'), (kuid_t) uid = ((uid_t)

(struct cred *) cred = 0xDDB71200 = -> ((atomic_t) usage = ((int) counter = 2 = 0x2 = '....'), (kuid_t) uid = ((uid_t) val =

(char [16]) comm = "mmcqd/0",

"mmcqd/0" 프로세스 콜스택은 아래와 같다.

-000|schedule()

-001|mmc_wait_for_data_req_done(inline)

-001|mmc_start_req(host = 0xC0F75D0C, areq = 0xC0F644E0, error = 0xC102CB08)

-002|mmc_blk_issue_rw_rq(mq = 0xDDB64408, rqc = 0x0)

-003|mmc_blk_issue_rq(mq = 0xDDB64408, req = 0x0)

-004|mmc_queue_thread(d = 0xDDB64408)

-005|kthread(_create = 0xDDB8BDC0)

-006|ret_from_fork(asm)

-007|ret_fast_syscall(asm)

mmc_wait_for_data_req_done 코드를 가보면, spin_lock_irqsave(&context_info->lock, flags); API를 통해 lock을 걸고 있었다.

static int mmc_wait_for_data_req_done(struct mmc_host *host,

struct mmc_request *mrq,

struct mmc_async_req *next_req)

{

struct mmc_command *cmd;

struct mmc_context_info *context_info = &host->context_info;

int err;

unsigned long flags;

while (1) {

wait_event_interruptible(context_info->wait,

(context_info->is_done_rcv ||

context_info->is_new_req));

spin_lock_irqsave(&context_info->lock, flags);

context_info->is_waiting_last_req = false;

조금 더 코드를 보면 Watchdog Reset이 trigger된 "ndroid.systemui" 프로세스 콜 스택에 아래 함수들이 있었다.

-003|mmc_wait_data_done

-004|msdc_irq_data_complete(host = 0xDD827280, ?, error = 0)

mmc_wait_data_done() 함수를 보면 mrq->host->context_info.is_done_rcv = true로 설정하고,

&mrq->host->context_info.wait wait queue을 깨우는 역할을 수행했다.

static void mmc_wait_data_done(struct mmc_request *mrq){

mrq->host->context_info.is_done_rcv = true;

wake_up_interruptible(&mrq->host->context_info.wait);

}

그런데 mmc_wait_for_data_req_done() 함수의 아래 구문은 context_info->is_done_rcv, context_info->is_new_req가 true가

될 때 까지 기다리는 코드다.

wait_event_interruptible(context_info->wait,

(context_info->is_done_rcv ||

context_info->is_new_req));

정리해보면, race condition으로 wake_up_interruptible(&mrq->host->context_info.wait); 함수를 통해 wait_queue에 queue된

&mrq->host->context_info.wait으로 등록된 프로세스를 깨우기 전에 아래 구문이 풀려버려 이미 깨어버린 경우임을 짐작할 수 있다.

잠을 자고 있는 누군가를 깨우려고 손을 대려고 하는데 이미 깨버린 경우와 비슷하네.

In-depth Analysis

내 추정이 맞다면 아래 코드를 삽입하면 바로 커널 패닉이 나야 한다.

(램덤프 force_mmc_wait_data_done_crash)

static void mmc_wait_data_done(struct mmc_request mrq){*

mrq->host->context_info.is_done_rcv = true;

+ mdelay(1);

wake_up_interruptible(&mrq->host->context_info.wait);

}

그런데 바로 커널 패닉이 발생했다.

-000|do_DataAbort(addr = 0, fsr = 0, regs = 0x0)

-001|__dabt_svc(asm)

-->|exception

-002|debug_spin_lock_before(inline)

-002|do_raw_spin_lock(lock = 0x02B4)

-003|raw_spin_lock_irqsave(lock = 0x02B4)

-004|__wake_up(q = 0x02B4, mode = 1, nr_exclusive = 1, key = 0x0)

-005|mmc_wait_data_done(mrq = 0xDC9725F8)

-006|msdc_irq_data_complete(host = 0xDC919300, ?, error = 0)

-007|msdc_irq(?, dev_id = 0x1)

-008|handle_irq_event_percpu(?, action = 0xDC91E0C0)

-009|handle_irq_event(desc = 0xC121A440)

-010|cond_unmask_eoi_irq(inline)

-010|handle_fasteoi_irq(?, desc = 0xC121A440)

-011|static_key_count(inline)

-011|static_key_false(inline)

-011|trace_irq_exit(inline)

-011|__handle_domain_irq(domain = 0xDE806000, hwirq = 111, lookup = TRUE, ?)

-012|__raw_readl(inline)

-012|gic_handle_irq(regs = 0xCB773E10)

-013|__irq_svc(asm)

-->|exception

-014|current_thread_info(inline)

-014|check_preemption_disabled(what1 = 0xC0F115AC, what2 = 0xC0EE0B28)

-015|debug_smp_processor_id()

-016|MT_trace_preempt_on()

-017|preempt_count_sub

-018|current_thread_info(inline)

-018|preempt_count(inline)

-018|should_resched(inline)

-018|__percpu_counter_add(fbc = 0xD8AC7178, amount = 0, batch = 32)

-019|__sb_start_write(sb = 0xC0F115AC, level = -1058141400, wait = FALSE)

-020|file_start_write(inline)

-020|vfs_write(file = 0xD366C480, buf = 0xBEA83A4C, ?, pos = 0xCB773F78)

-021|SYSC_write(inline)

-021|sys_write(?, buf = -1096271284, count = 146)

-022|ret_fast_syscall(asm)

mrq->host->context_info.wait 변수를 확인해보면, 이미 mrq->host 변수가 0이다.

(struct mmc_request *)0xDC9725F8 = 0xDC9725F8 -> (

sbc = 0xDC97262C,

cmd = 0xDC972660,

data = 0xDC9726C8,

stop = 0xDC972694,

completion = (done = 0x0, wait = (lock = (rlock = (raw_lock = (slock = 0x0,

done = 0x0,

host = 0x0)

어머 그런데, mmcqd/0 프로세스가 mmc_wait_for_data_req_done() 코드를 이미 수행했네?

-000|context_switch(inline)

-000|__schedule()

-001|schedule()

-002|mmc_wait_for_data_req_done(inline)

-002|mmc_start_req(host = 0xDC919000, areq = 0xDC972710, ?)

-003|mmc_blk_issue_rw_rq(mq = 0x0, rqc = 0xC64B18C0)

-004|mmc_blk_issue_rq(mq = 0xDC972494, req = 0xC64B18C0)

-005|mmc_queue_thread(d = 0xDC972494)

-006|kthread(_create = 0xDCA24E40)

-007|ret_from_fork(asm)

-008|ret_fast_syscall(asm)

@ftrace log를 좀 더 추가해보자.

diff --git a/drivers/mmc/core/core.c b/drivers/mmc/core/core.c

index db74413..fcf6692 100644

? a/drivers/mmc/core/core.c

+++ b/drivers/mmc/core/core.c

@@ -1034,6 +1034,9 @@ out:

}

EXPORT_SYMBOL(mmc_start_bkops);

#endif

mmc_wait_data_done() - done callback for data request

@mrq: done data request

@@ -1042,10 +1045,25 @@ EXPORT_SYMBOL(mmc_start_bkops);

static void mmc_wait_data_done(struct mmc_request *mrq)

static void mmc_wait_data_done(struct mmc_request mrq) *{

mrq->host->context_info.is_done_rcv = true;

+ trace_printk("+msdc [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0));

mdelay(1);

+ trace_printk("++msdc [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0));

wake_up_interruptible(&mrq->host->context_info.wait);

+ trace_printk("--msdc [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0));

역시나 GIC mtk-msdc(111) IRQ가 Trigger된 다음에 아래와 같이 커널 패닉이 발생하였네.

(램덤프: neo_more_crash_ftrace)

-000|do_DataAbort(addr = 0, fsr = 0, regs = 0x0)

-001|__dabt_svc(asm)

-->|exception

-002|debug_spin_lock_before(inline)

-002|do_raw_spin_lock(lock = 0x02B4)

-003|raw_spin_lock_irqsave(lock = 0x02B4)

-004|__wake_up(q = 0x02B4, mode = 1, nr_exclusive = 1, key = 0x0)

-005|mmc_wait_data_done(mrq = 0xDC9235F8)

-006|msdc_irq_data_complete(host = 0xDC927300, ?, error = 0)

-007|msdc_irq(?, dev_id = 0x1)

-008|handle_irq_event_percpu(?, action = 0xDC92B180)

-009|handle_irq_event(desc = 0xC121A440)

-010|cond_unmask_eoi_irq(inline)

-010|handle_fasteoi_irq(?, desc = 0xC121A440)

-011|static_key_count(inline)

-011|static_key_false(inline)

-011|trace_irq_exit(inline)

-011|__handle_domain_irq(domain = 0xDE806000, hwirq = 111, lookup = TRUE, ?)

-012|__raw_readl(inline)

-012|gic_handle_irq(regs = 0xC2631E20)

-013|__irq_svc(asm)

-->|exception

-014|__fget(?, mask = 16384)

-015|__fget_light(?, mask = 16384)

-016|__fdget

-017|sockfd_lookup_light(?, err = 0xC2631EC8, fput_needed = 0xC2631ECC)

-018|SYSC_recvfrom(inline)

-018|sys_recvfrom(?, ubuf = -1212542344, ?, flags = 64, addr = 0, addr_len = 0)

-019|ret_fast_syscall(asm)

Ftrace log 분석 좀 해보자.

커널 패닉이 일어나기 직전 상황

[1]: irq=111 name=mtk-msdc 가 Trigger됨

[2]: IRQ context에서 mmc_wait_data_done() 함수가 호출 from(msdc_irq_data_complete)

[2]~[3] 사이 mmcq0 process가 context switching 되지 않고 수행 ( InputDispatcher-1538)

[3]: mdelay(1); 이후 찍히는 ftrace log

[4]: wake_up_interruptible(&mrq->host->context_info.wait); API 호출로 mmcq0 process을 wakeup 시킴

CPU5: mmcqd/0, pid=244

sched_wakeup: comm=mmcqd/0 pid=244 prio=120 success=1 target_cpu=005 state=W

[5]: wake_up_interruptible(&mrq->host->context_info.wait); API 호출이 끝난 후 찍히는 로그(별 의미 없음)

kworker/4:0-25 [004] 149.827488: irq_handler_entry: irq=111 name=mtk-msdc // <<--[1]

kworker/4:0-25 [004] 149.827495: bprint: mmc_wait_data_done: +msdc [F: mmc_wait_data_done, L:1049]: ? ? from(msdc_irq_data_complete) // <<--[2]

InputDispatcher-1538 [005] 149.827496: sched_migrate_task: comm=m.lge.launcher3 pid=2135 prio=120 orig_cpu=6 dest_cpu=4 state=W

InputDispatcher-1538 [005] 149.827519: sched_wakeup: comm=m.lge.launcher3 pid=2135 prio=120 success=1 target_cpu=004 state=W

InputDispatcher-1538 [005] 149.827591: sched_migrate_task: comm=ndroid.systemui pid=1622 prio=120 orig_cpu=5 dest_cpu=6 state=W

InputDispatcher-1538 [005] 149.827608: sched_wakeup: comm=ndroid.systemui pid=1622 prio=120 success=1 target_cpu=006 state=W

InputDispatcher-1538 [005] 149.827675: sched_migrate_task: comm=android.ui pid=1287 prio=118 orig_cpu=4 dest_cpu=6 state=W

InputDispatcher-1538 [005] 149.827694: sched_wakeup: comm=android.ui pid=1287 prio=118 success=1 target_cpu=006 state=W

InputDispatcher-1538 [005] 149.827855: sched_switch: prev_comm=InputDispatcher prev_pid=1538 prev_prio=112 prev_state=S ==> next_comm=swapper/5 next_pid=0 next_prio=120 extra_prev_state=K|m|d

<idle>-0 [005] 149.827912: sched_switch: prev_comm=swapper/5 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=InputDispatcher next_pid=1538 next_prio=112 extra_prev_state=K|m|d

InputDispatcher-1538 [005] 149.828064: sched_switch: prev_comm=InputDispatcher prev_pid=1538 prev_prio=112 prev_state=S ==> next_comm=swapper/5 next_pid=0 next_prio=120 extra_prev_state=K|m|d

<idle>-0 [005] 149.828209: sched_switch: prev_comm=swapper/5 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=InputDispatcher next_pid=1538 next_prio=112 extra_prev_state=K|m|d

InputDispatcher-1538 [005] 149.828352: sched_switch: prev_comm=InputDispatcher prev_pid=1538 prev_prio=112 prev_state=S ==> next_comm=swapper/5 next_pid=0 next_prio=120 extra_prev_state=K|m|d

kworker/4:0-25 [004] 149.828497: bprint: mmc_wait_data_done: ++msdc [F: mmc_wait_data_done, L:1058]: ? ? from(msdc_irq_data_complete) // <<--[3]

kworker/4:0-25 [004] 149.828521: sched_wakeup: comm=mmcqd/0 pid=244 prio=120 success=1 target_cpu=005 state=W // <<--[4]

kworker/4:0-25 [004] 149.828525: bprint: mmc_wait_data_done: -msdc [F: mmc_wait_data_done, L:1060]: ? ? from(msdc_irq_data_complete) <<-[5]

<idle>0 [005] 149.828528: sched_switch: prev_comm=swapper/5 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=mmcqd/0 next_pid=244 next_prio=120 extra_prev_state=K|m|d <<-[6]

kworker/4:0-25 [004] 149.828530: irq_handler_exit: irq=111 ret=handled

1046 static void mmc_wait_data_done(struct mmc_request *mrq)

1047*{*

1048 mrq->host->context_info.is_done_rcv = true;

1049 trace_printk("+msdc [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0)); // <<--[2]

//생략

1051 mdelay(1);

//생략

1057

1058 trace_printk("++msdc [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0)); // <<--[3]

1059 wake_up_interruptible(&mrq->host->context_info.wait);

1060 trace_printk("-msdc [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0)); // <<-[5]

커널 패닉 상황

[7]: irq=111 name=mtk-msdc 가 handle 되었음

[8]: [mmcqd/0-244, CPU5]mmc_wait_for_data_req_done() 함수 내[from(mmc_blk_issue_rw_rq)] wait_event_interruptible()에서 빠져나옴.

[9][10]: [mmcqd/0-244, CPU5]mmc_wait_for_data_req_done() 함수를 빠져나옴

[11]: irq=111 name=mtk-msdc 가 Trigger됨 --> CPU4의 m.lge.launcher3-2135

[12]: [mmcqd/0-244, CPU5] 깨어난 mmcqd/0-244 프로세스 활동 시작

&mqrq->brq 변수를 0으로 밀어버림 (where: memset(brq, 0, sizeof(struct mmc_blk_request));

[13]: [m.lge.launcher3-2135 CPU4] irq=111 name=mtk-msdc IRQ로 Trigger되어 실행되어

mmc_wait_data_done() 함수 진입

[14][15]: [mmcqd/0-244, CPU5] mmc_blk_rw_rq_prep() 함수 퇴장하려함

[16][17][18] [mmcqd/0-244, CPU5] mmc_wait_for_data_req_done() 함수 처리 후 퇴장하려함

[19]: [m.lge.launcher3-2135 CPU4] wake_up_interruptible(&mrq->host->context_info.wait);

[20] 커널 패닉

[12]번 동작에서 0으로 초기화된 &mrq->host 변수를 통해 밀린((where: memset(brq, 0, sizeof(struct mmc_blk_request)) wake_up_interruptible() API 호출

kworker/4:0-25 [004] 149.828530: irq_handler_exit: irq=111 ret=handled // <<--[7]

mmcqd/0-244 [005] 149.828536: bprint: mmc_start_req: ++mmcq [F: mmc_wait_for_data_req_done, L:1236]: ? ? from(mmc_blk_issue_rw_rq) // <<--[8]

kworker/4:0-25 [004] 149.828537: irq_handler_entry: irq=30 name=arch_timer

kworker/4:0-25 [004] 149.828546: irq_handler_exit: irq=30 ret=handled

mmcqd/0-244 [005] 149.828559: bprint: mmc_start_req: mmcq [F: mmc_wait_for_data_req_done, L:1268]: ? ? from(mmc_blk_issue_rw_rq) // <<-[9]

mmcqd/0-244 [005] 149.828561: bprint: mmc_start_req: mmcq release [F: mmc_wait_for_data_req_done, L:1270]: ? ? from(mmc_blk_issue_rw_rq) // <<--[10]

kworker/4:0-25 [004] 149.828584: workqueue_execute_end: work struct 0xcb40cae4

kworker/4:0-25 [004] 149.828630: sched_switch: prev_comm=kworker/4:0 prev_pid=25 prev_prio=120 prev_state=S ==> next_comm=m.lge.launcher3 next_pid=2135 next_prio=120 extra_prev_state=K|m|d

m.lge.launcher3-2135 [004] 149.828660: irq_handler_entry: irq=111 name=mtk-msdc // <<--[11]

mmcqd/0-244 [005] 149.828661: bprint: mmc_blk_rw_rq_prep: ++mmc_blk_rw_rq_prep [F: mmc_blk_rw_rq_prep, L:1725]: ? ? from(mmc_blk_issue_rw_rq) // <<--[12]

m.lge.launcher3-2135 [004] 149.828666: bprint: mmc_wait_data_done: +msdc [F: mmc_wait_data_done, L:1049]: ? ? from(msdc_irq_data_complete) // <<--[13]

mmcqd/0-244 [005] 149.828670: bprint: mmc_blk_rw_rq_prep: -mmc_blk_rw_rq_prep [F: mmc_blk_rw_rq_prep, L:1905]: ? ? from(mmc_blk_issue_rw_rq) // <<-[14]

mmcqd/0-244 [005] 149.828672: bprint: mmc_blk_rw_rq_prep: mmc_blk_rw_rq_prep [F: mmc_blk_rw_rq_prep, L:1907]: ? ? from(mmc_blk_issue_rw_rq) // <<-[15]

mmcqd/0-244 [005] 149.828681: bprint: mmc_start_req: +mmcq [F: mmc_wait_for_data_req_done, L:1231]: ? ? from(mmc_blk_issue_rw_rq) // <<--[16]

mmcqd/0-244 [005] 149.828683: bprint: mmc_start_req: ++mmcq [F: mmc_wait_for_data_req_done, L:1236]: ? ? from(mmc_blk_issue_rw_rq) // <<--[17]

mmcqd/0-244 [005] 149.828695: bprint: mmc_start_req: -mmcq [F: mmc_wait_for_dat뗥nQ, L:0]: ? ? from(0x726f776bS) // <<--[18]

m.lge.launcher3-2135 [004] 149.829669: bprint: mmc_wait_data_done: ++msdc [F: mmc_wait_data_done, L:1058]: ? ? from(msdc_irq_data_complete) // <<--[19]

m.lge.launcher3-2135 [004] 149.829748: tracing_on: ftrace is disabled caller=oops_enter // <<?[20]

1222 static int mmc_wait_for_data_req_done(struct mmc_host *host,

1223 struct mmc_request *mrq,

1224 struct mmc_async_req *next_req)

1225*{*

1226 struct mmc_command *cmd;

1227 struct mmc_context_info *context_info = &host->context_info;

1228 int err;

1229 unsigned long flags;

1230

1231 trace_printk("+mmcq [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0)); // <<--[16]

1232 while (1) {

1233 wait_event_interruptible(context_info->wait,

1234 (context_info->is_done_rcv ||

1235 context_info->is_new_req));

1236 trace_printk("++mmcq [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0)); // <<--[8], [17]

1237 spin_lock_irqsave(&context_info->lock, flags);

//snip

1268 trace_printk("mmcq [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0)); // <<-[9], [18]

1269 mmc_retune_release(host);

1270 trace_printk("mmcq release [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0));

1271 return err;

1272 }

1701 static void mmc_blk_rw_rq_prep(struct mmc_queue_req *mqrq,

1702 struct mmc_card *card,

1703 int disable_multi,

1704 struct mmc_queue *mq)

1705*{*

1706 u32 readcmd, writecmd;

1707 struct mmc_blk_request *brq = &mqrq->brq;

//생략

1724 memset(brq, 0, sizeof(struct mmc_blk_request));

1725 trace_printk("++mmc_blk_rw_rq_prep [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0)); // <<--[12]

1726 brq->mrq.cmd = &brq->cmd;

//생략

1905 trace_printk("-mmc_blk_rw_rq_prep [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0)); //<<-[14]

1906 mmc_queue_bounce_pre(mqrq);

1907 trace_printk("-mmc_blk_rw_rq_prep [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0));

1908 }

1046 static void mmc_wait_data_done(struct mmc_request *mrq)

1047*{*

1048 mrq->host->context_info.is_done_rcv = true;

1049 trace_printk("+msdc [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0)); // <<--[13]

//생략

1051 mdelay(1);

//생략

1057

1058 trace_printk("++msdc [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0)); // <<--[19]

1059 wake_up_interruptible(&mrq->host->context_info.wait);

1060 trace_printk("--msdc [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0));

정리하면 wake_up_interruptible() API에 파라미터로 전달되는 &mrq->host->context_info.wait를 다른 값(mmcqd를 깨울 수 있는 wait_queue)으로 바꾸거나,

wake_up_interruptible() 호출 시 조건을 줘야 한다. 혹은 spinlock irq save로 코드 보호

솔류션

분석된 내용에 따라 아래 패치를 적용하였더니 문제가 사라졌다.

diff --git a/drivers/mmc/core/core.c b/drivers/mmc/core/core.c

index c3abe34..01e4bfc 100644

--- a/drivers/mmc/core/core.c

+++ b/drivers/mmc/core/core.c

@@ -403,8 +403,13 @@ EXPORT_SYMBOL(mmc_start_bkops);

static void mmc_wait_data_done(struct mmc_request *mrq)

{

+ unsigned long flags;

+ struct mmc_context_info *context_info = &mrq->host->context_info;

+ spin_lock_irqsave(&context_info->lock, flags);

mrq->host->context_info.is_done_rcv = true;

wake_up_interruptible(&mrq->host->context_info.wait);

+ spin_unlock_irqrestore(&context_info->lock, flags);

}

static void mmc_wait_done(struct mmc_request *mrq)

@@ -465,6 +470,7 @@ static int mmc_wait_for_data_req_done(struct mmc_host *host,

struct mmc_command *cmd;

struct mmc_context_info *context_info = &host->context_info;

int err;

+ bool is_done_rcv = false;

unsigned long flags;

while (1) {

@@ -472,9 +478,10 @@ static int mmc_wait_for_data_req_done(struct mmc_host *host,

(context_info->is_done_rcv ||

context_info->is_new_req));

spin_lock_irqsave(&context_info->lock, flags);

+ is_done_rcv = context_info->is_done_rcv;

context_info->is_waiting_last_req = false;

spin_unlock_irqrestore(&context_info->lock, flags);

- if (context_info->is_done_rcv) {

+ if (is_done_rcv) {

context_info->is_done_rcv = false;

context_info->is_new_req = false;

cmd = mrq->cmd;

그런데, 리눅스 커뮤니티에서 이미 패치를 릴리즈했네.

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

diff --git a/drivers/mmc/core/core.c b/drivers/mmc/core/core.c

index 347108a..db74413 100644

--- a/drivers/mmc/core/core.c

+++ b/drivers/mmc/core/core.c

@@ -1042,8 +1042,10 @@ EXPORT_SYMBOL(mmc_start_bkops);

static void mmc_wait_data_done(struct mmc_request *mrq)

{

- mrq->host->context_info.is_done_rcv = true;

- wake_up_interruptible(&mrq->host->context_info.wait);

+ struct mmc_context_info *context_info = &mrq->host->context_info;

+ context_info->is_done_rcv = true;

+ wake_up_interruptible(&context_info->wait);

}

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

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

http://www.yes24.com/Product/Goods/90085976

https://wikibook.co.kr/linux-kernel-1/

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

http://www.yes24.com/Product/Goods/90087307

https://wikibook.co.kr/linux-kernel-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
[Kernel][Debug] "cat /d/shrinker" kernel panic (0)	2023.05.07

PREV 이전 1 2 3 NEXT 다음

Arm Linux Kernel Hacks