早いもので2月も下旬となってしまいました.
2025年もあれよあれよというまに1/6が過ぎようとしてます、光陰矢のごとし.
今回も前回同様にテックネタで.
Table of Contents
プログラムが異常終了するとのレポート
他の部署からこちらが書いたプログラムが異常終了するとの連絡.
(そういう連絡にはログを付けるのが常識だと思うのだが…それもなし…愚痴でした)
ログをもらうとKernelログには SIGSEGV が発生した形跡が.
[17111.810474] hogehoge[10852]: segfault at 0 ip 0000000000000000 sp 00007ffc127c0bb8 error 14 in hogehoge[635e0316e000+1000] likely on CPU 2 (core 2, socket 0)
[17111.810509] Code: Unable to access opcode bytes at 0xffffffffffffffd6.
さて, 問題を解析するために, ログの中身の意味, このログがどのように表示されたのかを調べてみました,
このエラーを再現する
以下のようなテストコードを書いて実行すると先のKernel ログが再現できました.
#include <stdio.h>
int (*funcp)(int,int) = NULL;
int main()
{
printf ("hello world\n");
funcp(10,10);
return 0;
}NULLに設定した関数ポインタ funcp を実行しています. このプログラムを実行したときの dmesg は以下の通りです
[ 4954.799760] segfault[6059]: segfault at 0 ip 0000000000000000 sp 00007fffacb32808 error 14 in segfault[5a8f64a74000+1000] likely on CPU 0 (core 0, socket 0)
[ 4954.799775] Code: Unable to access opcode bytes at 0xffffffffffffffd6.
さて、このログを意味, そしてこれを表示させているのはどこでしょうか?
segfaultログを出しているところ
先のsegfaultログを出力しているのは, Linux Kernel の arch/x86/mm/fault.c の show_signal_msg() です.
ディレクトリ名からもわかる通り, x86系CPUの独自コードとなっており, ARMなど他のCPUでは別の実装となっている(はず)点に注意してください.
/*
* Print out info about fatal segfaults, if the show_unhandled_signals
* sysctl is set:
*/
static inline void
show_signal_msg(struct pt_regs *regs, unsigned long error_code,
unsigned long address, struct task_struct *tsk)
{
const char *loglvl = task_pid_nr(tsk) > 1 ? KERN_INFO : KERN_EMERG;
/* This is a racy snapshot, but it's better than nothing. */
int cpu = raw_smp_processor_id();
if (!unhandled_signal(tsk, SIGSEGV))
return;
if (!printk_ratelimit())
return;
printk("%s%s[%d]: segfault at %lx ip %px sp %px error %lx",
loglvl, tsk->comm, task_pid_nr(tsk), address,
(void *)regs->ip, (void *)regs->sp, error_code);
print_vma_addr(KERN_CONT " in ", regs->ip);
/*
* Dump the likely CPU where the fatal segfault happened.
* This can help identify faulty hardware.
*/
printk(KERN_CONT " likely on CPU %d (core %d, socket %d)", cpu,
topology_core_id(cpu), topology_physical_package_id(cpu));
printk(KERN_CONT "\n");
show_opcodes(regs, loglvl);
}SIGSEGVが発生したプロセス(スレッド)名, アドレス, プロセスIDなどが表示されますが, 着目すべきは error_code です. SIGSEGV が発生した要因が error_code として格納されています.
[ 4954.799760] segfault[6059]: segfault at 0 ip 0000000000000000 sp 00007fffacb32808 error 14 in segfault[5a8f64a74000+1000] likely on CPU 0 (core 0, socket 0)
ここでは, error 14 となっていますが, その値は asm-generic/errno-base.h で以下のように定義されてます.
/* SPDX-License-Identifier: GPL-2.0 WITH Linux-syscall-note */
#ifndef _ASM_GENERIC_ERRNO_BASE_H
#define _ASM_GENERIC_ERRNO_BASE_H
#define EPERM 1 /* Operation not permitted */
#define ENOENT 2 /* No such file or directory */
#define ESRCH 3 /* No such process */
#define EINTR 4 /* Interrupted system call */
#define EIO 5 /* I/O error */
#define ENXIO 6 /* No such device or address */
#define E2BIG 7 /* Argument list too long */
#define ENOEXEC 8 /* Exec format error */
#define EBADF 9 /* Bad file number */
#define ECHILD 10 /* No child processes */
#define EAGAIN 11 /* Try again */
#define ENOMEM 12 /* Out of memory */
#define EACCES 13 /* Permission denied */
#define EFAULT 14 /* Bad address */
#define ENOTBLK 15 /* Block device required */
#define EBUSY 16 /* Device or resource busy */
#define EEXIST 17 /* File exists */
#define EXDEV 18 /* Cross-device link */
#define ENODEV 19 /* No such device */
#define ENOTDIR 20 /* Not a directory */
#define EISDIR 21 /* Is a directory */
#define EINVAL 22 /* Invalid argument */
#define ENFILE 23 /* File table overflow */
#define EMFILE 24 /* Too many open files */
#define ENOTTY 25 /* Not a typewriter */
#define ETXTBSY 26 /* Text file busy */
#define EFBIG 27 /* File too large */
#define ENOSPC 28 /* No space left on device */
#define ESPIPE 29 /* Illegal seek */
#define EROFS 30 /* Read-only file system */
#define EMLINK 31 /* Too many links */
#define EPIPE 32 /* Broken pipe */
#define EDOM 33 /* Math argument out of domain of func */
#define ERANGE 34 /* Math result not representable */
#endiferror 14 は EFAULT “Bad address” となっており, NULL Pointer を実行したことによるエラーであることがわかります.
また, ip レジスタが 0000000000000000 となっていることから, NULL Pointer を実行したことが推測されます.
このようにログの error 値とレジスタによっておおよその原因を解析する手助けとなります.
別のエラーログを見る
先とは少しだけ違うログを見る機会がありました.
それがこちら
[ 5756.770130] sigsegv[4473]: segfault at 0 ip 00005ba6b606b16b sp 00007ffe137b07e0 error 4 in sigsegv[5ba6b606b000+1000] likely on CPU 0 (core 0, socket 0)
[ 5756.770146] Code: 0f 1e fa e9 77 ff ff ff f3 0f 1e fa 55 48 89 e5 48 83 ec 10 48 8d 05 a8 0e 00 00 48 89 c7 e8 ec fe ff ff 48 8b 05 ad 2e 00 00 <8b> 00 89 45 fc b8 00 00 00 00 c9 c3 00 f3 0f 1e fa 48 83 ec 08 48
先ほどのログと同じく segfault が発生し, そのときのレジスタ値, error 値が表示されてます.
今回の error 値は 4 ですので, EINTR Interrupted system call ということがまずわかります.
上記 segfault が発生したコードはこちら.
#include <stdio.h>
int *intp = NULL;
int main()
{
printf ("hello world\n");
int a = *intp;
return 0;
}NULL Pointer からデータをアクセスしようとしています.
さて, 先ほどの NULL の関数ポインタを実行した際と少し違って, 何やらダンプリストのようなものが表示しています.
ダンプリストを表示してるのはどこだ?
先ほどのダンプリストを表示しているのは, Linux Kernel の arch/x86/kernel/dumpstack.c の show_opcodes() です.
void show_opcodes(struct pt_regs *regs, const char *loglvl)
{
#define PROLOGUE_SIZE 42
#define EPILOGUE_SIZE 21
#define OPCODE_BUFSIZE (PROLOGUE_SIZE + 1 + EPILOGUE_SIZE)
u8 opcodes[OPCODE_BUFSIZE];
unsigned long prologue = regs->ip - PROLOGUE_SIZE;
switch (copy_code(regs, opcodes, prologue, sizeof(opcodes))) {
case 0:
printk("%sCode: %" __stringify(PROLOGUE_SIZE) "ph <%02x> %"
__stringify(EPILOGUE_SIZE) "ph\n", loglvl, opcodes,
opcodes[PROLOGUE_SIZE], opcodes + PROLOGUE_SIZE + 1);
break;
case -EPERM:
/* No access to the user space stack of other tasks. Ignore. */
break;
default:
printk("%sCode: Unable to access opcode bytes at 0x%lx.\n",
loglvl, prologue);
break;
}
}関数引数 struct pt_regs *regs は, SIGSEGV 発生時のレジスタ値を格納した構造体です.
関数冒頭で,
#define PROLOGUE_SIZE 42
<snip>
unsigned long prologue = regs->ip - PROLOGUE_SIZE;としてますが, SIGSEGV 発生時のアドレス(ip) から 42バイト分さかのぼったアドレスを prologue に格納してます.
そして, copy_code() によって, prologue に示されたアドレスからコードバッファである opcodes へ OPCODE_BUFSIZE 分 (42 + 1 + 21 バイト) をコピーします.
copy_code() が成功すれば 0 を返します. 失敗したら
default:
printk("%sCode: Unable to access opcode bytes at 0x%lx.\n",
loglvl, prologue);が実行されます.
先の 先ほどの NULL の関数ポインタを実行した際, ip レジスタは 0 でしたので, コピー開始のポインタである prologue は -42 となり, メモリアクセスできないので
[ 4954.799775] Code: Unable to access opcode bytes at 0xffffffffffffffd6.
というログ表示になっているのです.
さて, copy_code() が成功すれば
case 0:
printk("%sCode: %" __stringify(PROLOGUE_SIZE) "ph <%02x> %"
__stringify(EPILOGUE_SIZE) "ph\n", loglvl, opcodes,
opcodes[PROLOGUE_SIZE], opcodes + PROLOGUE_SIZE + 1);
break;が実行されるわけですが, 普段 printf () の書式を見慣れてる身としては少し違和感を感じます.
はたしてこのコードがダンプリストを表示することができるのか?
printfk() の書式
先ほどの printk() の引数にあった __stringify() は引数を文字列に変換するマクロです.
printk() を書き直すとこんな感じになります.
case 0:
printk("%sCode: %42ph <%02x> %21ph\n", loglvl, opcodes,
opcodes[PROLOGUE_SIZE], opcodes + PROLOGUE_SIZE + 1);
break;さらに Documentation/core-api/printk-formats.rst を読むと,
Raw buffer as a hex string
--------------------------
::
%*ph 00 01 02 ... 3f
%*phC 00:01:02: ... :3f
%*phD 00-01-02- ... -3f
%*phN 000102 ... 3f
For printing small buffers (up to 64 bytes long) as a hex string with a
certain separator. For larger buffers consider using
と書かれてました.
すなわち printk() の書式のうち %42ph は 42バイト分の hex dump を表示, %21ph は 21バイト分のhex dump を表示することがわかります.
つまり, このコードは
- SIGSEGV が発生する前 42 バイト分のコードをダンプ.
- SIGSEGV が発生したコードを <> で表示.
- SIGSEGV が発生する後 21 バイト分のコードをダンプ.
を行っていることがわかりました.
プログラムを objdump してみると,
0000000000001149 <main>:
#include <stdio.h>
int *intp = NULL;
int main()
{
1149: f3 0f 1e fa endbr64
114d: 55 push %rbp
114e: 48 89 e5 mov %rsp,%rbp
1151: 48 83 ec 10 sub $0x10,%rsp
printf ("hello world\n");
1155: 48 8d 05 a8 0e 00 00 lea 0xea8(%rip),%rax # 2004 <_IO_stdin_used+0x4>
115c: 48 89 c7 mov %rax,%rdi
115f: e8 ec fe ff ff call 1050 <puts@plt>
int a = *intp;
1164: 48 8b 05 ad 2e 00 00 mov 0x2ead(%rip),%rax # 4018 <intp>
116b: 8b 00 mov (%rax),%eax
116d: 89 45 fc mov %eax,-0x4(%rbp)
return 0;
1170: b8 00 00 00 00 mov $0x0,%eax
}
1175: c9 leave
1176: c3 ret
SIGSEGV が発生したコード <8b> はNULL Pointer からアクセスした箇所に該当することがわかります.
このような手法で小さいプログラムならどこでSIGSEGVが発生したか、あたりをつけることも可能です.
では
![[Linux] Dynamic Link Library の話 その１、あなたのプログラムはどの *.so を使ってるの?](https://konpeitoh.net/wp-content/uploads/2022/02/IMG_3913-150x150.jpg)
![[Linux] setsockopt (SO_BINDTODEVICE) の Kernel Codeをちょっと読んでみた話](https://konpeitoh.net/wp-content/uploads/2022/01/IMG_3521-150x150.jpg)