와.. 대박... 일이 엄청나게 들어와..
공격적으로 오라클 리눅스를 장사하면 내가 쓰일만한 일이 있긴 하구나 하면서도
일이 이렇게 많아지면 개빡쳐서 아무것도 하기 싫어지는 현자타임같은게 온다는..
무튼, 요즘 핫하게 밀려들어오는 업무량 덕에 코어분석 일도 숭풍숭풍 막 쳐 들어오는..
이번에는 레드햇 커널 즉, Oracle Linux 에서 Cmompatibility 를 위해 제공하는
Redhat Compatible Kernel ( RHCK ) 와 관련된 커널 덤프 분석을 해주시겠다.
오늘은 보너스로 debug info 를 이용하는 것을 조금 더 알려주겠다.(사실 이런건 기본이잖아... 젖먹는거와도 같다고....)
$ rpm2cpio /share/linuxrpm/debuginfo-rpms/build-output-6-debuginfo/kernel-debuginfo-2.6.32-642.el6.x86_64.rpm |cpio -ivd
./usr/lib/debug
./usr/lib/debug/.build-id
./usr/lib/debug/.build-id/00
....
대강 풀어 준 뒤, 자 이제 들어가자 Crash 로!!
crash7latest> sys
KERNEL: /share/linuxrpm/vmlinux_repo/64/2.6.32-642.el6.x86_64/vmlinux
DUMPFILE: vmcore
CPUS: 16
DATE: Sun Feb 11 02:05:27 2018
UPTIME: 237 days, 23:45:59
LOAD AVERAGE: 5.72, 5.15, 3.66
TASKS: 3093
NODENAME: ****02
RELEASE: 2.6.32-642.el6.x86_64
VERSION: #1 SMP Tue May 10 12:00:56 PDT 2016
MACHINE: x86_64 (3495 Mhz)
MEMORY: 127.9 GB
PANIC: "[20568855.389826] kernel BUG at fs/fscache/operation.c:460!"
이젠 뭐 귀찮아서 그냥 sys 로만 간단히 본다
2월 11일 오전 2시경 리붓되었고, 사용중인 커널버젼은 2.6.32-642, OL 6.8 GA 이다.
당연하게 로그를 봐야겠지?
[5242336.027593] nfs: server 10.219.1.249 not responding, timed out
[5242339.028547] nfs: server 10.219.1.249 not responding, still trying
[5242339.029133] nfs: server 10.219.1.249 OK
[5251518.769273] nfs: server 10.219.1.249 not responding, still trying
[5251524.772508] nfs: server 10.219.1.249 OK
...
[20568855.389184] FS-Cache:
[20568855.389343] FS-Cache: Assertion failed
[20568855.389495] FS-Cache: 0 > 0 is false
[20568855.389674] ------------[ cut here ]------------
[20568855.389826] kernel BUG at fs/fscache/operation.c:460!
[20568855.389977] invalid opcode: 0000 [#1] SMP
[20568855.390134] last sysfs file: /sys/devices/system/cpu/online
[20568855.390284] CPU 11
[20568855.390290]
Modules linked in: iptable_filter ip_tables joydev nfs lockd
auth_rpcgss nfs_acl sunrpc symap_rh_ES_6_2_6_32_431_el6_x86_64(P)(U)
symev_rh_ES_6_2_6_32_431_el6_x86_64(U) cpufreq_ondemand freq_table
pcc_cpufreq cachefiles fscache(T) bonding ipv6 iTCO_wdt
iTCO_vendor_support microcode serio_raw power_meter acpi_ipmi ipmi_si
ipmi_msghandler sb_edac edac_core sg i2c_i801 i2c_core lpc_ich mfd_core
tg3 hpilo hpwdt ioatdma ixgbe dca ptp pps_core mdio ext4 jbd2 mbcache
sr_mod cdrom sd_mod crc_t10dif ahci xhci_hcd hpsa wmi dm_mirror
dm_region_hash dm_log dm_mod [last unloaded: scsi_wait_scan]
[20568855.391789]
[20568855.391934]
Pid: 78, comm: events/11 Tainted: P -- ------------ T
2.6.32-642.el6.x86_64 #1 HP ProLiant DL360 Gen9/ProLiant DL360 Gen9
[20568855.392240] RIP: 0010:[<ffffffffa03797fd>] [<ffffffffa03797fd>] fscache_op_complete+0x13d/0x1b0 [fscache]
[20568855.392540] RSP: 0018:ffff881069673d50 EFLAGS: 00010282
[20568855.392688] RAX: 0000000000000031 RBX: ffff88104973c980 RCX: 00000000000079b4
[20568855.392975] RDX: 0000000000000000 RSI: 0000000000000046 RDI: 0000000000000246
[20568855.393265] RBP: ffff881069673d70 R08: 0000000000000000 R09: ffff8800000b99a0
[20568855.393554] R10: 0000000000000000 R11: 0000000000000029 R12: ffff8810452b0540
[20568855.393843] R13: ffff8810452b0540 R14: 0000000000000001 R15: 0000160000000000
[20568855.394140] FS: 0000000000000000(0000) GS:ffff8800283c0000(0000) knlGS:0000000000000000
[20568855.394429] CS: 0010 DS: 0018 ES: 0018 CR0: 000000008005003b
[20568855.394577] CR2: 00007f541c71ccd8 CR3: 000000078f346000 CR4: 00000000001407e0
[20568855.394868] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[20568855.395159] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[20568855.395446] Process events/11 (pid: 78, threadinfo ffff881069670000, task ffff88106965e040)
[20568855.395739] Stack:
[20568855.395883] ffff881069670000 ffff8807945bfa40 ffff8810452b0540 6db6db6db6db6db7
[20568855.396041] <d> ffff881069673e10 ffffffffa03935f5 ffff8800283d9d00 ffff88104973c980
[20568855.396345] <d> ffff881069673fd8 ffff880000000000 ffff8807945bfa80 ffff88104973c980
[20568855.396953] Call Trace:
[20568855.397102] [<ffffffffa03935f5>] cachefiles_read_copier+0x385/0x440 [cachefiles]
[20568855.397395] [<ffffffffa037a760>] ? fscache_retrieval_work+0x0/0x30 [fscache]
[20568855.397688] [<ffffffffa037a77b>] fscache_retrieval_work+0x1b/0x30 [fscache]
[20568855.397980] [<ffffffff8109fdc0>] worker_thread+0x170/0x2a0
[20568855.398130] [<ffffffff810a6ac0>] ? autoremove_wake_function+0x0/0x40
[20568855.398280] [<ffffffff8109fc50>] ? worker_thread+0x0/0x2a0
[20568855.398430] [<ffffffff810a662e>] kthread+0x9e/0xc0
[20568855.398580] [<ffffffff8100c28a>] child_rip+0xa/0x20
[20568855.398730] [<ffffffff810a6590>] ? kthread+0x0/0xc0
[20568855.398878] [<ffffffff8100c280>] ? child_rip+0x0/0x20
[20568855.399026]
Code: a0 31 c0 e8 d9 d6 1c e1 48 c7 c7 58 d2 37 a0 31 c0 e8 cb d6 1c e1
49 63 74 24 20 31 d2 48 c7 c7 78 d2 37 a0 31 c0 e8 b6 d6 1c e1
<0f> 0b eb fe 48 c7 c7 eb e9 37 a0 31 c0 e8 a4 d6 1c e1 48 c7 c7
[20568855.399656] RIP [<ffffffffa03797fd>] fscache_op_complete+0x13d/0x1b0 [fscache]
[20568855.399951] RSP <ffff881069673d50>
역시 로그만 보면 큰 의미가 없다.
일단, NFS 랑 fscache / cachefiles 요녀석들이 말썽의 원인같다.
이 fscache / cachefiles 는 커널 2.6.32.X 부터 지원되기 시작했으며,
Redhat/Oracle Linux 6.x 부터 Technical Preview 로 제공되는 커널 기능이다.
자세한건 LWN 기사 또는 커널문서를 참조하자. 찾아보면 많다. 좋다.
( https://lwn.net/Articles/176487/ )
다음으로 진행하기 전에 이 fscache 모듈들을 로드하자.
crash7latest> mod -s fscache usr/lib/debug/lib/modules/2.6.32-642.el6.x86_64/kernel/fs/fscache/fscache.ko.debug
MODULE NAME SIZE OBJECT FILE
ffffffffa037fce0 fscache 60813 usr/lib/debug/lib/modules/2.6.32-642.el6.x86_64/kernel/fs/fscache/fscache.ko.debug
crash7latest> mod -s fscache usr/lib/debug/lib/modules/2.6.32-642.el6.x86_64/kernel/fs/fscache/fscache.ko.debug
MODULE NAME SIZE OBJECT FILE
ffffffffa037fce0 fscache 60813 usr/lib/debug/lib/modules/2.6.32-642.el6.x86_64/kernel/fs/fscache/fscache.ko.debug
crash7latest> bt -l
PID: 78 TASK: ffff88106965e040 CPU: 11 COMMAND: "events/11"
#0 [ffff881069673a10] machine_kexec at ffffffff8103fdcb
/usr/src/debug/kernel-2.6.32-642.el6/linux-2.6.32-642.el6.x86_64/arch/x86/kernel/machine_kexec_64.c: 336
#1 [ffff881069673a70] crash_kexec at ffffffff810d1fe2
/usr/src/debug/kernel-2.6.32-642.el6/linux-2.6.32-642.el6.x86_64/kernel/kexec.c: 1110
#2 [ffff881069673b40] oops_end at ffffffff8154bc40
/usr/src/debug/kernel-2.6.32-642.el6/linux-2.6.32-642.el6.x86_64/arch/x86/kernel/dumpstack.c: 245
#3 [ffff881069673b70] die at ffffffff8101102b
/usr/src/debug/kernel-2.6.32-642.el6/linux-2.6.32-642.el6.x86_64/arch/x86/kernel/dumpstack.c: 325
#4 [ffff881069673ba0] do_trap at ffffffff8154b494
/usr/src/debug/kernel-2.6.32-642.el6/linux-2.6.32-642.el6.x86_64/arch/x86/kernel/traps.c: 244
#5 [ffff881069673c00] do_invalid_op at ffffffff8100cd95
/usr/src/debug/kernel-2.6.32-642.el6/linux-2.6.32-642.el6.x86_64/arch/x86/kernel/traps.c: 285
#6 [ffff881069673ca0] invalid_op at ffffffff8100c01b
/usr/src/debug/kernel-2.6.32-642.el6/linux-2.6.32-642.el6.x86_64/arch/x86/kernel/entry_64.S: 1144
[exception RIP: fscache_op_complete+317]
RIP: ffffffffa03797fd RSP: ffff881069673d50 RFLAGS: 00010282
RAX: 0000000000000031 RBX: ffff88104973c980 RCX: 00000000000079b4
RDX: 0000000000000000 RSI: 0000000000000046 RDI: 0000000000000246
RBP: ffff881069673d70 R8: 0000000000000000 R9: ffff8800000b99a0
R10: 0000000000000000 R11: 0000000000000029 R12: ffff8810452b0540
R13: ffff8810452b0540 R14: 0000000000000001 R15: 0000160000000000
ORIG_RAX: ffffffffffffffff CS: 0010 SS: 0018
/usr/src/debug/kernel-2.6.32-642.el6/linux-2.6.32-642.el6.x86_64/fs/fscache/operation.c: 460
#7 [ffff881069673d78] cachefiles_read_copier at ffffffffa03935f5 [cachefiles]
#8 [ffff881069673e18] fscache_retrieval_work at ffffffffa037a77b [fscache]
/usr/src/debug/kernel-2.6.32-642.el6/linux-2.6.32-642.el6.x86_64/fs/fscache/page.c: 269
#9 [ffff881069673e38] worker_thread at ffffffff8109fdc0
/usr/src/debug/kernel-2.6.32-642.el6/linux-2.6.32-642.el6.x86_64/kernel/workqueue.c: 316
#10 [ffff881069673ee8] kthread at ffffffff810a662e
/usr/src/debug/kernel-2.6.32-642.el6/linux-2.6.32-642.el6.x86_64/kernel/kthread.c: 88
#11 [ffff881069673f48] kernel_thread at ffffffff8100c28a
/usr/src/debug/kernel-2.6.32-642.el6/linux-2.6.32-642.el6.x86_64/arch/x86/kernel/entry_64.S: 1238
crash7latest>
다 귀찮다 그냥 쭉 본다. 돈줄거냐? 돈 필요없다. 그냥 설명 안한다. ㅎ
crash7latest> dis -rl ffffffffa03797fd
......
0xffffffffa03796ee <fscache_op_complete+46>: jne 0xffffffffa0379801 <fscache_op_complete+321>
/usr/src/debug/kernel-2.6.32-642.el6/linux-2.6.32-642.el6.x86_64/fs/fscache/operation.c: 460
0xffffffffa03796f4 <fscache_op_complete+52>: mov 0x20(%r12),%eax
0xffffffffa03796f9 <fscache_op_complete+57>: test %eax,%eax
0xffffffffa03796fb <fscache_op_complete+59>: jle 0xffffffffa03797cc <fscache_op_complete+268>
/usr/src/debug/kernel-2.6.32-642.el6/linux-2.6.32-642.el6.x86_64/fs/fscache/operation.c: 461
0xffffffffa0379701 <fscache_op_complete+65>: testb $0x20,0x40(%rdi)
0xffffffffa0379705 <fscache_op_complete+69>: jne 0xffffffffa037977f <fscache_op_complete+191>
/usr/src/debug/kernel-2.6.32-642.el6/linux-2.6.32-642.el6.x86_64/fs/fscache/operation.c: 466
0xffffffffa0379707 <fscache_op_complete+71>: lea 0x2c(%r12),%r13
0xffffffffa037970c <fscache_op_complete+76>: mov %r13,%rdi
0xffffffffa037970f <fscache_op_complete+79>: callq 0xffffffff8154a9b0 <_spin_lock>
/usr/src/debug/kernel-2.6.32-642.el6/linux-2.6.32-642.el6.x86_64/fs/fscache/operation.c: 468
0xffffffffa0379714 <fscache_op_complete+84>: test %r14b,%r14b
0xffffffffa0379717 <fscache_op_complete+87>: jne 0xffffffffa0379770 <fscache_op_complete+176>
/usr/src/debug/kernel-2.6.32-642.el6/linux-2.6.32-642.el6.x86_64/fs/fscache/operation.c: 469
0xffffffffa0379719 <fscache_op_complete+89>: movl $0x4,0x48(%rbx)
/usr/src/debug/kernel-2.6.32-642.el6/linux-2.6.32-642.el6.x86_64/fs/fscache/operation.c: 475
0xffffffffa0379720 <fscache_op_complete+96>: testb $0x20,0x40(%rbx)
0xffffffffa0379724 <fscache_op_complete+100>: jne 0xffffffffa0379760 <fscache_op_complete+160>
/usr/src/debug/kernel-2.6.32-642.el6/linux-2.6.32-642.el6.x86_64/fs/fscache/operation.c: 477
0xffffffffa0379726 <fscache_op_complete+102>: mov 0x20(%r12),%eax
0xffffffffa037972b <fscache_op_complete+107>: sub $0x1,%eax
/usr/src/debug/kernel-2.6.32-642.el6/linux-2.6.32-642.el6.x86_64/fs/fscache/operation.c: 478
0xffffffffa037972e <fscache_op_complete+110>: test %eax,%eax
/usr/src/debug/kernel-2.6.32-642.el6/linux-2.6.32-642.el6.x86_64/fs/fscache/operation.c: 477
0xffffffffa0379730 <fscache_op_complete+112>: mov %eax,0x20(%r12)
/usr/src/debug/kernel-2.6.32-642.el6/linux-2.6.32-642.el6.x86_64/fs/fscache/operation.c: 478
0xffffffffa0379735 <fscache_op_complete+117>: jne 0xffffffffa037973f <fscache_op_complete+127>
/usr/src/debug/kernel-2.6.32-642.el6/linux-2.6.32-642.el6.x86_64/fs/fscache/operation.c: 479
0xffffffffa0379737 <fscache_op_complete+119>: mov %r12,%rdi
0xffffffffa037973a <fscache_op_complete+122>: callq 0xffffffffa03795e0 <fscache_start_operations>
/usr/src/debug/kernel-2.6.32-642.el6/linux-2.6.32-642.el6.x86_64/arch/x86/include/asm/spinlock.h: 174
0xffffffffa037973f <fscache_op_complete+127>: mov %r13,%rax
0xffffffffa0379742 <fscache_op_complete+130>: incw (%rax)
0xffffffffa0379745 <fscache_op_complete+133>: data32 xchg %ax,%ax
/usr/src/debug/kernel-2.6.32-642.el6/linux-2.6.32-642.el6.x86_64/fs/fscache/operation.c: 483
0xffffffffa0379748 <fscache_op_complete+136>: mov (%rsp),%rbx
0xffffffffa037974c <fscache_op_complete+140>: mov 0x8(%rsp),%r12
0xffffffffa0379751 <fscache_op_complete+145>: mov 0x10(%rsp),%r13
0xffffffffa0379756 <fscache_op_complete+150>: mov 0x18(%rsp),%r14
0xffffffffa037975b <fscache_op_complete+155>: leaveq
0xffffffffa037975c <fscache_op_complete+156>: retq
0xffffffffa037975d <fscache_op_complete+157>: nopl (%rax)
/usr/src/debug/kernel-2.6.32-642.el6/linux-2.6.32-642.el6.x86_64/fs/fscache/operation.c: 476
0xffffffffa0379760 <fscache_op_complete+160>: subl $0x1,0x24(%r12)
0xffffffffa0379766 <fscache_op_complete+166>: jmp 0xffffffffa0379726 <fscache_op_complete+102>
0xffffffffa0379768 <fscache_op_complete+168>: nopl 0x0(%rax,%rax,1)
/usr/src/debug/kernel-2.6.32-642.el6/linux-2.6.32-642.el6.x86_64/fs/fscache/operation.c: 471
0xffffffffa0379770 <fscache_op_complete+176>: mov %rbx,%rdi
0xffffffffa0379773 <fscache_op_complete+179>: callq *0x60(%rbx)
/usr/src/debug/kernel-2.6.32-642.el6/linux-2.6.32-642.el6.x86_64/fs/fscache/operation.c: 472
0xffffffffa0379776 <fscache_op_complete+182>: movl $0x5,0x48(%rbx)
0xffffffffa037977d <fscache_op_complete+189>: jmp 0xffffffffa0379720 <fscache_op_complete+96>
/usr/src/debug/kernel-2.6.32-642.el6/linux-2.6.32-642.el6.x86_64/fs/fscache/operation.c: 461
0xffffffffa037977f <fscache_op_complete+191>: cmpl $0x0,0x24(%r12)
0xffffffffa0379785 <fscache_op_complete+197>: jle 0xffffffffa0379837 <fscache_op_complete+375>
/usr/src/debug/kernel-2.6.32-642.el6/linux-2.6.32-642.el6.x86_64/fs/fscache/operation.c: 463
0xffffffffa037978b <fscache_op_complete+203>: cmp $0x1,%eax
0xffffffffa037978e <fscache_op_complete+206>: je 0xffffffffa0379707 <fscache_op_complete+71>
0xffffffffa0379794 <fscache_op_complete+212>: mov $0xffffffffa037e9eb,%rdi
0xffffffffa037979b <fscache_op_complete+219>: xor %eax,%eax
0xffffffffa037979d <fscache_op_complete+221>: callq 0xffffffff81546eb3 <printk>
0xffffffffa03797a2 <fscache_op_complete+226>: mov $0xffffffffa037d258,%rdi
0xffffffffa03797a9 <fscache_op_complete+233>: xor %eax,%eax
0xffffffffa03797ab <fscache_op_complete+235>: callq 0xffffffff81546eb3 <printk>
0xffffffffa03797b0 <fscache_op_complete+240>: movslq 0x20(%r12),%rsi
0xffffffffa03797b5 <fscache_op_complete+245>: mov $0x1,%edx
0xffffffffa03797ba <fscache_op_complete+250>: mov $0xffffffffa037d2a0,%rdi
0xffffffffa03797c1 <fscache_op_complete+257>: xor %eax,%eax
0xffffffffa03797c3 <fscache_op_complete+259>: callq 0xffffffff81546eb3 <printk>
0xffffffffa03797c8 <fscache_op_complete+264>: ud2
0xffffffffa03797ca <fscache_op_complete+266>: jmp 0xffffffffa03797ca <fscache_op_complete+266>
/usr/src/debug/kernel-2.6.32-642.el6/linux-2.6.32-642.el6.x86_64/fs/fscache/operation.c: 460
0xffffffffa03797cc <fscache_op_complete+268>: mov $0xffffffffa037e9eb,%rdi
0xffffffffa03797d3 <fscache_op_complete+275>: xor %eax,%eax
0xffffffffa03797d5 <fscache_op_complete+277>: callq 0xffffffff81546eb3 <printk>
0xffffffffa03797da <fscache_op_complete+282>: mov $0xffffffffa037d258,%rdi
0xffffffffa03797e1 <fscache_op_complete+289>: xor %eax,%eax
0xffffffffa03797e3 <fscache_op_complete+291>: callq 0xffffffff81546eb3 <printk>
0xffffffffa03797e8 <fscache_op_complete+296>: movslq 0x20(%r12),%rsi
0xffffffffa03797ed <fscache_op_complete+301>: xor %edx,%edx
0xffffffffa03797ef <fscache_op_complete+303>: mov $0xffffffffa037d278,%rdi
0xffffffffa03797f6 <fscache_op_complete+310>: xor %eax,%eax
0xffffffffa03797f8 <fscache_op_complete+312>: callq 0xffffffff81546eb3 <printk>
0xffffffffa03797fd <fscache_op_complete+317>: ud2
crash7latest> evval 0x13d
crash7latest: command not found: evval
crash7latest> eval 0x13d
hexadecimal: 13d
decimal: 317
octal: 475
binary: 0000000000000000000000000000000000000000000000000000000100111101
crash7latest> x/s 0xffffffffa037d258
0xffffffffa037d258:
"<3>FS-Cache: Assertion failed\n"
<<
crash7latest> x/s 0xffffffffa037d278
0xffffffffa037d278:
"<3>FS-Cache: %lx > %lx is false\n"
<<
crash7latest> x/s 0xffffffffa037e9eb
0xffffffffa037e9eb:
"<3>FS-Cache: \n"
<<
crash7latest> x/s ffff8810452b0540
No symbol "ffff8810452b0540" in current context.
gdb: gdb request failed: x/s ffff8810452b0540
crash7latest> x/s 0xffff8810452b0540
0xffff8810452b0540: "\240\314\067\240\377\377\377\377@\314\067\240\377\377\377\377\tF\024"
crash7latest> rd ffff8810452b0540 32
ffff8810452b0540: ffffffffa037cca0 ffffffffa037cc40 ..7.....@.7.....
ffff8810452b0550: 0000000000144609 0000000000000001 .F..............
ffff8810452b0560: 0000000000000000 0006000600000001 ................
ffff8810452b0570: 00000005c99820b8 0000000000000060 . ......`.......
ffff8810452b0580: 000000000000006d 0000000000000010 m...............
ffff8810452b0590: 0000000000000038 ffff8810452b0718 8.........+E....
ffff8810452b05a0: ffff882065bf5678 0000000000000000 xV.e ...........
ffff8810452b05b0: ffff8810489b5b08 ffff882065bf5600 .[.H.....V.e ...
ffff8810452b05c0: ffff8810489b5af0 ffff880b7baa5b00 .Z.H.....[.{....
ffff8810452b05d0: 0000000000000000 0000000000000008 ................
ffff8810452b05e0: ffffffffa037c940 ffff8810452b05e8 @.7.......+E....
ffff8810452b05f0: ffff8810452b05e8 ffff8810452b05f8 ..+E......+E....
ffff8810452b0600: ffff8810452b05f8 ffff8810452b0608 ..+E......+E....
ffff8810452b0610: ffff8810452b0608 ffff8810452b0618 ..+E......+E....
ffff8810452b0620: ffff8810452b0618 0000000000000023 ..+E....#.......
ffff8810452b0630: 000000000002295e 0000000000000000 ^)..............
crash7latest> dis -rl ffffffffa037cca0
0xffffffffa037cca0
<fscache_osm_WAIT_FOR_CMD>: push %rdi
<<
자, Disassembly 로 까보니 printk 가 문제 코드 근처에 존재했을 뿐이고,
printk 가 뭔가 출력해 주는 짓을 할테니 그 곳에 무언가 스트링이나
값이 들어가있을 것이기 때문에, 각 변수들의 내용을 String 으로 출력해 보니,
대략의 코드내용을 얻을 수 있었다.
해당 내용은 위에 log 에서 cut here 바로 앞에 나온다 :
[20568855.389184] FS-Cache:
[20568855.389343] FS-Cache: Assertion failed
[20568855.389495] FS-Cache: 0 > 0 is false
딱 봐도 뭔가 개 구린 코드다. 개띠해라고 개 구리냐..
코드를 보자. 오라클 리눅스에서는 gitlab 을 운영하므로 웹에서 쉽게 볼 수 있는데,
레드햇은 참 나쁘다. 안보여준다. 계정 돈내고 가입하라고 한다.
열심히 찾아본다. 소스코드 받는다... 제길 귀찮다...
무튼 아래와 같은 오퍼레이션 코드와 문제의 Function 이 확인된다.
--- include/linux/fscache-cache.h
enum fscache_operation_state {
FSCACHE_OP_ST_BLANK, /* Op is not yet submitted */
<<<
FSCACHE_OP_ST_INITIALISED, /* Op is initialised */
FSCACHE_OP_ST_PENDING, /* Op is blocked from running */
FSCACHE_OP_ST_IN_PROGRESS, /* Op is in progress */
FSCACHE_OP_ST_COMPLETE, /* Op is complete */
FSCACHE_OP_ST_CANCELLED, /* Op has been cancelled */
FSCACHE_OP_ST_DEAD /* Op is now dead */
};
--- kernel/fs/fscache/operation.c
void fscache_op_complete(struct fscache_operation *op, bool cancelled)
{
struct fscache_object *object = op->object;
_enter("OBJ%x", object->debug_id);
ASSERTCMP(op->state, ==, FSCACHE_OP_ST_IN_PROGRESS);
ASSERTCMP(object->n_in_progress, >, 0);
ASSERTIFCMP(test_bit(FSCACHE_OP_EXCLUSIVE, &op->flags),
object->n_exclusive, >, 0);
ASSERTIFCMP(test_bit(FSCACHE_OP_EXCLUSIVE, &op->flags),
object->n_in_progress, ==, 1);
object->n_in_progress 가 0 보다 크면 무언가 하는 매크로가 존재한다.
--- fs/fscache/internal.h
#define ASSERTCMP(X, OP, Y) do {} while (0)
단순하다. 0이 될 때 까지 해당 값을 감소시키는 코드로 보여진다.
Disassem 으로 본 내용역시 460 에서 483 갔다가 476 등으로 가는등
루프백 점핑이 확인된다.
0 이라는 in_progress 값이 FSCACHE_OP_ST_BLANK 이며,
설명에 Op is not yet submitted 라고되어 있다.
Race condition 등이 발생하여 해당 값을 제대로 처리하지 못한 부분이
패닉으로 발생한 것으로 판단된다.
실재 맞는 프로그레스 상태인지 확인해 보도록 하자.
스택을 일일히 확인하는 방법 또는 Memory Dump 와 Structure Offset 을 이용해
직접 계산해 보는 방법이 있는데, 스택으로 들어있는 주소를 그냥 찾아보는게
훨씬 빠르고 간편하고 틀린 방법이 아니므로, 그냥 대입한다.
스택에 대한 부분은 아까 위에 로그나 BT 등에서 Stack 이라고 표시되거나 색처리 했다.
(훌륭한 학습 방법은 직접 따라해보거나 흐름을 잘 눈 크게 뜨고 살피는것이다.)
crash7latest> struct fscache_operation ffff881069670000
struct fscache_operation {
{
fast_work = {
data = {
counter = -131870907572160
},
entry = {
next = 0xffffffff81aabb80 <default_exec_domain>,
prev = 0x0
},
func = 0xb
},
slow_work = {
owner = 0xffff88106965e040,
flags = 18446744071590034304,
ops = 0x0,
link = {
next = 0xb,
prev = 0xffffffffffffffff
}
}
},
pend_link = {
next = 0xffffffff810917e0 <do_no_restart_syscall>,
prev = 0x0
},
object = 0x0,
flags = 0,
state = FSCACHE_OP_ST_BLANK,
usage = {
counter = 0
},
debug_id = 0,
processor = 0x0,
cancel = 0x0,
release = 0x57ac6e9d
}
crash7latest> struct fscache_operation ffffffffa037cca0
struct fscache_operation {
{
fast_work = {
data = {
counter = 5931036609520157015
},
entry = {
next = 0x444d435f,
prev = 0x0
},
func = 0x444d433f
},
slow_work = {
owner = 0x524f465f54494157,
flags = 1145914207,
ops = 0x0,
link = {
next = 0x444d433f,
prev = 0x0
}
}
},
pend_link = {
next = 0x8,
prev = 0xffffffffa037cde0 <fscache_osm_INVALIDATE_OBJECT>
},
object = 0x4,
flags = 18446744072102595872,
state = FSCACHE_OP_ST_INITIALISED,
usage = {
counter = 0
},
debug_id = 2688011360,
processor = 0x0,
cancel = 0x0,
release = 0x0
}
crash7latest> struct fscache_operation ffffffffa037cc40
struct fscache_operation {
{
fast_work = {
data = {
counter = 96
},
entry = {
next = 0xffffffffa037c960 <fscache_osm_KILL_OBJECT>,
prev = 0x0
},
func = 0x0
},
slow_work = {
owner = 0x60,
flags = 18446744072102594912,
ops = 0x0,
link = {
next = 0x0,
prev = 0x52415453504d554a
}
}
},
pend_link = {
next = 0x535045445f54,
prev = 0x0
},
object = 0x504d554a,
flags = 18446744072102578672,
state = FSCACHE_OP_ST_BLANK,
usage = {
counter = 0
},
debug_id = 0,
processor = 0x0,
cancel = 0x524f465f54494157,
release = 0x444d435f
}
Task 에 대한 구조체 값을 확인함으로 써 state 변화를 확인할 수 있다.
역시 in_progress 상태를 지속적으로 확인하고 변화시키는 과정에서 문제가 발생했다.
Technical Preview 이기 때문에 해당 부분에 대한 코드는
ASSERTCMP(op->state, ==, FSCACHE_OP_ST_DEAD);
로 수정되는 식으로 상황을 정리하는 코드가 추가된 것 같다.
( 수정된 코드 다운받거나 찾기 귀찮다! 바쁘다. 점심안에 써야한다 글을. )
물론 픽스는 해당 fscache 모듈을 사용하지 않도록 하거나,
( cachefilesd 데몬을 Disable 한다. )
ELSA-2017-0307 또는 ELSA-2017-0817 ( RHSA-2017-0817 대응) 에서 권고하는
kernel-2.6.32-696.el6 이후의 최신 버젼으로 업그레이드 하거나
6.8 GA kernel-2.6.32-642.el6 이하 커널로 다운그레이드 하면 된다고
Redhat 에서 이야기 하는 것 같다.
사실 개인생각으로는 커널 업그레이드를 해봤자 동일할것 같긴 해서
구지 필요하지 않다면 Cachefilesd 를 Off 하는게 더 좋을것 같다고 생각된다.
mount option 에서 fsc 가 생겼는데 이게 없으면 자동으로 fscache 가 활성화 된다고 하는 것 같다.
레드햇 이슈라 명확하게 솔루션 코드가 확인되지 않는 상태라 잘 모르겠으나
분석 방법이랑 워크어라운드 기입되 있음 이미 난 충분히 세계를 위해 기여한거시다...
'Skills > mY Technutz' 카테고리의 다른 글
| Kernel Dump Analysis #17 (0) | 2019.04.04 |
|---|---|
| libfc: Update rport reference counting bug - 1368175 (0) | 2018.03.29 |
| Kernel Dump Analysis #15 (0) | 2018.02.19 |
| Kernel Dump Analysis #14 (0) | 2018.02.13 |
| Kernel Crash dump Analysis - #13 (0) | 2017.12.20 |