セキュリティ対策室の伊藤洋也 @hiboma です。
業務中に、Haconiwa コンテナ で動くとある node プロセスが general protection fault ( 一般保護違反! ) を起こしてdmesg にログを残す現象を調べ、問題解決にあたっていました。その際の痕跡をまとめなおして記したエントリになります。
エントリの概要
本エントリでは、以下のような内容を扱います。
- Haconiwa コンテナの node プロセスが general protection fault を起こしている
- ライブラリ関数 abort(3) の概要
- abort(3) がプロセスを停止する方法の検証
- node プロセスが abort(3) を呼び出すケース
- glibc x86系の abort(3) 実装が HLT 命令を呼び出し、general protection fault を起こすこと
- node.js の node::ResetStdio() の概要
- コンテナの PID 1 のプロセスで abort(3) を呼び出すと general protection fault を起こす
読者に届けたいもの
Linux 低レイヤーでのトラブルシューティングのプロセスを公開し、社内外に知見を共有する目的で書き記しています。
- 業務中に遭遇したリアルな問題をもとにトラブルシューティングの事例紹介
- ログ、ソース、ドキュメントを突き合わせながら、事象の裏付けをとり問題を明らかにしていくアプローチの紹介
- glibc, Linux Kernel, x86, gdb, strace … 等々を得意とする人たちへの「おやつ」提供
.. をお届け出来ればと思います。
node が abort(3) で general protection fault を起こしたログ
さて、今回 私が追いかけた プロセス は、 dmesg に general protection fault = 一般保護例外 のログを出していました。
dmesg
実際に業務中に採取した dmesg です。
May 22 19:04:47 *** kernel: [4586113.110719] traps: node[14610] general protection fault ip:7f0291cb7196 sp:7fff48570020 error:0 in libc-2.23.so[7f0291c80000+1c0000]
May 22 19:04:47 *** kernel: [4586113.110730] potentially unexpected fatal signal 11.
May 22 19:04:47 *** kernel: [4586113.110733] CPU: 4 PID: 14610 Comm: node Kdump: loaded Not tainted 5.3.9-050309-generic #201911061337
May 22 19:04:47 *** kernel: [4586113.110734] Hardware name: ****, BIOS ****
May 22 19:04:47 *** kernel: [4586113.110738] RIP: 0033:0x7f0291cb7196
May 22 19:04:47 *** kernel: [4586113.110741] Code: 05 0f 85 e6 fd ff ff bf 06 00 00 00 c7 05 7e ea 38 00 06 00 00 00 e8 69 e2 ff ff 8b 05 73 ea 38 00 83 f8 06 0f 85 cc fd ff ff <f4> bf 7f 00 00 00 c7 05 5a ea 38 00 08 00 00 00 e8 65 55 09 00 0f
May 22 19:04:47 *** kernel: [4586113.110742] RSP: 002b:00007fff48570020 EFLAGS: 00010246
May 22 19:04:47 *** kernel: [4586113.110745] RAX: 0000000000000006 RBX: 0000000001c12a10 RCX: ffffffffffffff00
May 22 19:04:47 *** kernel: [4586113.110746] RDX: 00007f0292f21740 RSI: 00007f0292046770 RDI: 00007f0292045540
May 22 19:04:47 *** kernel: [4586113.110747] RBP: 00007fff48570150 R08: 00007f0292046770 R09: 00007f0292f21740
May 22 19:04:47 *** kernel: [4586113.110748] R10: 0000000000000006 R11: 0000000000000000 R12: 84bda12f684bda13
May 22 19:04:47 *** kernel: [4586113.110749] R13: 0000000000000001 R14: 0000000000008000 R15: 0000000000000000
May 22 19:04:47 *** kernel: [4586113.110750] FS: 00007f0292f21740 GS: 0000000000000000
💡 ホスト名やハードウェアを特定できる部分にマスクを入れています
general protection fault を起こして signal 11 = SIGSEGV を受けて停止しています。
ログを残したプロセスは node (npm) です。プロセスは、コンテナ環境、正確に言えば Haconiwa を利用した環境で動いていました。調べていくうちに、node (npm) プロセス停止時に上記の dmesg を出して異常停止し、数十分毎に再現する周期性を持つ特徴を発見します。
さて、このようなログを手掛かりにどうやって調べていきましょうか?
gdb で調査する
各種の制約で、コンテナの設定や環境に手を加えるのが難しく、プロセス停止時のコアを採取できなかったため、まずは稼働しているプロセスに gdb でアタッチして糸口を探りました。
gdb でプロセスにアタッチし RIP を disassemble します。すると、abort(3) の呼び出しであることが分かりました。
(gdb) disas 0x7ffff6d82196
Dump of assembler code for function abort: 👈
0x00007ffff6d81ec0 <+0>: int3
0x00007ffff6d81ec1 <+1>: sub $0x128,%esp
0x00007ffff6d81ec7 <+7>: mov %fs:0x10,%rdx
0x00007ffff6d81ed0 <+16>: cmp 0x38ed21(%rip),%rdx # 0x7ffff7110bf8
0x00007ffff6d81ed7 <+23>: je 0x7ffff6d81f1f <abort+95>
0x00007ffff6d81ed9 <+25>: mov $0x1,%esi
0x00007ffff6d81ede <+30>: xor %eax,%eax
... 略
0x00007ffff6d8216d <+685>: jne 0x7ffff6d81f59 <abort+153>
0x00007ffff6d82173 <+691>: mov $0x6,%edi
0x00007ffff6d82178 <+696>: movl $0x6,0x38ea7e(%rip) # 0x7ffff7110c00
0x00007ffff6d82182 <+706>: callq 0x7ffff6d803f0 <raise>
0x00007ffff6d82187 <+711>: mov 0x38ea73(%rip),%eax # 0x7ffff7110c00
0x00007ffff6d8218d <+717>: cmp $0x6,%eax
0x00007ffff6d82190 <+720>: jne 0x7ffff6d81f62 <abort+162>
0x00007ffff6d82196 <+726>: hlt 🔥
0x00007ffff6d82197 <+727>: mov $0x7f,%edi
0x00007ffff6d8219c <+732>: movl $0x8,0x38ea5a(%rip) # 0x7ffff7110c00
0x00007ffff6d821a6 <+742>: callq 0x7ffff6e17710 <_exit>
💡 sysctl kernel.randomize_va_space =0 で ALSR = address space layout randomization を無効にしてから再現を確認し調査をしました。これによって RIP がランダム化されないので gdb で追いかけるのが容易になります。
🔥 が general protection fault を起こした RIP のディスアセンブル箇所です。 abort(3) の中に HLT 命令が ? なんなのだこれは?
man で abort(3) を調べる
HLT 命令が気になるところですが、いったん脇において、初心にかえって abort(3) がどういうライブラリ関数なのかを確かめ直しました。
abort(3) の man を読むと以下の通りの説明が付いています。
abort() 関数は、まず SIGABRT の禁止 (block) を解除してから、 (raise(3) が呼び出されたかのように) 呼び出し元のプロセスに SIGABRT シグナルを上げる。その結果、 SIGABRT シグナルが捕捉 (caught) されて対応するシグナルハンドラーが 返って来ない場合以外は、プログラムの異常終了が起こる (longjmp(3) 参照)。 abort() 関数によってプロセスの終了が引き起こされたときには、 すべての開いているストリームは閉じられフラッシュされる。
SIGABRT シグナルが無視、または返って来るシグナルハンドラーで 捕捉されるようになっている場合であっても、 abort() 関数はそのプロセスを終了する。 SIGABRT シグナルに対する処理方法をデフォルトに戻してから、再度 SIGABRT シグナルを上げることで、このような動作になる。
💡linuxjm.osdn.jp の翻訳は http://man7.org/linux/man-pages/man3/abort.3.html と同等の翻訳になっていたので、日本の読者向けに翻訳を引用しています。
HLT 命令に関する記述は特にないですね 🤔
abort(3) の検証
小さなコードを書いて abort(3) の検証を行いました。
#include <stdlib.h>
void main() {
abort();
}
abort(3) を呼び出して、プロセスは停止する! Aborted !
$ ./a.out
Aborted (core dumped)
さて、Linux では
sysctl kernel.print-fatal-signals=1sysctl debug.exception-trace=1
を設定すると dmesg に プロセスが異常停止した際の詳細を出すことができます (例: SIGSEGV, SIGABRT 等を受けて停止するケース) 。以下のログは、検証時に取った dmesg です。
[19406.703560] potentially unexpected fatal signal 6.
[19406.703562] CPU: 0 PID: 13773 Comm: a.out Tainted: G C OE 4.15.0-20-generic #21-Ubuntu
[19406.703563] Hardware name: innotek GmbH VirtualBox/VirtualBox, BIOS VirtualBox 12/01/2006
[19406.703565] RIP: 0033:0x7f9807e9ae97
[19406.703566] RSP: 002b:00007fffb287e5f0 EFLAGS: 00000246 ORIG_RAX: 000000000000000e
[19406.703567] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 00007f9807e9ae97
## [19406.703568] RDX: 0000000000000000 RSI: 00007fffb287e5f0 RDI: 0000000000000002
[19406.703568] RBP: 00007fffb287e840 R08: 0000000000000000 R09: 00007fffb287e5f0
[19406.703569] R10: 0000000000000008 R11: 0000000000000246 R12: 0000558697fd8540
[19406.703569] R13: 00007fffb287e920 R14: 0000000000000000 R15: 0000000000000000
[19406.703570] FS: 00007f98084694c0(0000) GS:ffff9e653fc00000(0000) knlGS:0000000000000000
[19406.703571] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[19406.703572] CR2: 00007f9807e9f430 CR3: 0000000073cea002 CR4: 00000000000606f0
potentially unexpected fatal signal 6 、つまり、シグナル番号 6 で停止した旨が書き出されています。 番号 6 は SIGABRT です。
$ grep -R SIGABRT /usr/include/asm-generic/signal.h
#define SIGABRT 6
うーん、冒頭にみたログとは違い general protection fault と SIGSEGV では無いですね 🤔
strace でトレースする
abort(3) を起こす際に strace をとってみます。
tgkill(2) で SIGABRT を自スレッド ( ここではプロセスと同等 ) に送っているのが観察できます。
vagrant@ubuntu1810:~$ strace -e tgkill ./a.out
tgkill(13809, 13809, SIGABRT) = 0
--- SIGABRT {si_signo=SIGABRT, si_code=SI_TKILL, si_pid=13809, si_uid=1000} ---
+++ killed by SIGABRT (core dumped) +++
Aborted (core dumped)
ここまでは abort(3) の 「表の顔」 とでも言うべき挙動です。次に 「裏の顔」 をみていきましょう
abort(3) の glibc 実装を追う
abort の話に戻ります。HLT 命令の呼び出しが気になるので、glibc がどのように abort(3) を実装しているか、ソースを追いかけました。glibc-2.27 のソースを掲載します。
stdlib/abort.c
/* Cause an abnormal program termination with core-dump. */
void
abort (void)
{
struct sigaction act;
sigset_t sigs;
/* First acquire the lock. */
__libc_lock_lock_recursive (lock);
/* Now it's for sure we are alone. But recursive calls are possible. */
/* Unblock SIGABRT. */
if (stage == 0) 👈
{
++stage;
__sigemptyset (&sigs);
__sigaddset (&sigs, SIGABRT);
__sigprocmask (SIG_UNBLOCK, &sigs, 0);
}
/* Send signal which possibly calls a user handler. */
if (stage == 1) 👈
{
/* This stage is special: we must allow repeated calls of
`abort' when a user defined handler for SIGABRT is installed.
This is risky since the `raise' implementation might also
fail but I don't see another possibility. */
int save_stage = stage;
stage = 0;
__libc_lock_unlock_recursive (lock);
raise (SIGABRT); 🔥
__libc_lock_lock_recursive (lock);
stage = save_stage + 1;
}
/* There was a handler installed. Now remove it. */
if (stage == 2) 👈
{
++stage;
memset (&act, '\0', sizeof (struct sigaction));
act.sa_handler = SIG_DFL;
__sigfillset (&act.sa_mask);
act.sa_flags = 0;
__sigaction (SIGABRT, &act, NULL);
}
/* Try again. */
if (stage == 3) 👈
{
++stage;
raise (SIGABRT); 🔥
}
/* Now try to abort using the system specific command. */
if (stage == 4)
{
++stage;
ABORT_INSTRUCTION; 🔥🔥🔥
}
/* If we can't signal ourselves and the abort instruction failed, exit. */
if (stage == 5) 👈
{
++stage;
_exit (127); 🔥
}
/* If even this fails try to use the provided instruction to crash
or otherwise make sure we never return. */
while (1)
/* Try for ever and ever. */
ABORT_INSTRUCTION; 🔥
}
libc_hidden_def (abort)
🔥でアノテートしたコードは、プロセスの停止を試みている部分です。
なるほど、abort は ステージ を分け、それぞれでプロセスを停止する術を変える実装になってますね !!!
abort のステージ
- raise(SIGABRT) での停止を試みる
- ABORT_INSTRUCTION での停止を試みる
- _exit(127) での停止を試みる
- 無限ループして ABORT_INSTRUCTION で停止を試みる
「 abort(3) がどうやって general protection fault を起こしたのか？」 という疑問に対して ABORT_INSTRUCTION が答えのキーとなります。実は、x86 アーキテクチャで ABORT_INSTRUCTION は HLT 命令を実行するマクロになっています。
/* An instruction which should crash any program is `hlt'. */
#define ABORT_INSTRUCTION asm ("hlt")
コメント文が興味深いですね。
次は HLT 命令について調べていきました。(どんどん脇道に逸れている気がしますが、トラブルシューティングでは、問題に回帰するポイントを見失ってはいけませんね )
HLT 命令とは何か?
『IA-32インテル® アーキテクチ-ャ・ソフトウェア・デベロッパーズ・マニュアル 中巻A:命令セット・リファレンスA-M』を参照しました。
命令の実行を停止し、プロセッサを HALT 状態にする。イネーブルにされている割り 込み(NMI および SMI を含む)、デバッグ例外、BINIT# 信号、INIT# 信号、RESET# 信 号によって実行が再開される。
HLT 命令の後で割り込み(NMI を含む)を使用して実 行を再開する場合、セーブされている命令ポインタ(CS:EIP)は HLT 命令の次の命令 を指している。
ハイパー・スレッディング・テクノロジに対応した IA-32 プロセッサ上で HLT 命令を 実行した場合は、HLT 命令を実行した論理プロセッサだけが HALT 状態になる。物理 プロセッサ内のそれ以外の論理プロセッサは、HLT 命令を実行することで個別に HALT 状態にされない限り、アクティブのままになる。
引用:『IA-32インテル® アーキテクチャ・ソフトウェア・デベロッパーズ・マニュアル 中巻A:命令セット・リファレンスA-M』 3-360
さらに特権レベルについての説明が続きます。
HLT 命令は特権命令である。プロセッサが保護モードまたは仮想 8086 モードで動作し ている場合は、HLT 命令を実行するには、プログラムまたはプロシージャの特権レベ ルが 0 でなければならない。
HLT 命令は 特権レベル (Ring) 0 で実行可能な特権命令である。ここが大事です。
ユーザ空間での HLT 命令呼び出し -> general protection fault 🔥
「特権レベル」について確認しましょう。
プロセッサは特権レベルを使用して、低い特権レベルで動 作しているプログラムまたはタスクが高い特権レベルのセグメントにアクセスしな いようにする。プロセッサは、特権レベル違反を検出すると、一般保護例外(#GP) を生成する。
引用:『IA-32インテル® アーキテクチャ・ソフトウェア・デベロッパーズ・マニュアル 下巻:システム・プログラミング・ガイド』4.5. 特権レベル
では、上記に倣って Linux での挙動を整頓してみます。
- Linux x86 系で ユーザ空間 ( = Ring 3 ) で動作するプロセスが、 HLT 命令 ( Ring 0 の特権レベルが必要 ) を呼び出す
- CPU が 特権レベル違反を検知して general protection fault を起こす
- fault を カーネルがハンドリングし、該当のプロセスに SIGSEGV を飛ばして停止を試みる
ということになりそうです。Linux カーネルのソースも合わせて確かめます。
general proection fault から Linux Kernel へ
CPU が起こす general protection fault を、Linxu カーネルは do_general_protection () でハンドリングします。 do_general_protection () は、IDT = Interrupt Descriptor Table で登録された割り込みハンドラです。( このへんの説明は割愛します。OS の実装を取り扱ったドキュメント、技術書、サイトを参考にしてください )
do_general_protection() in arch/x86/kernel/traps.c
- 👈 dmesg のログを出力するコード
- 🔥 SIGSEGV を送りつけるコード
となっています。
dotraplinkage void
do_general_protection(struct pt_regs *regs, long error_code)
{
struct task_struct *tsk;
RCU_LOCKDEP_WARN(!rcu_is_watching(), "entry code didn't wake RCU");
cond_local_irq_enable(regs);
if (static_cpu_has(X86_FEATURE_UMIP)) {
if (user_mode(regs) && fixup_umip_exception(regs))
return;
}
if (v8086_mode(regs)) {
local_irq_enable();
handle_vm86_fault((struct kernel_vm86_regs *) regs, error_code);
return;
}
tsk = current;
if (!user_mode(regs)) {
if (fixup_exception(regs, X86_TRAP_GP))
return;
tsk->thread.error_code = error_code;
tsk->thread.trap_nr = X86_TRAP_GP;
if (notify_die(DIE_GPF, "general protection fault", regs, error_code,
X86_TRAP_GP, SIGSEGV) != NOTIFY_STOP)
die("general protection fault", regs, error_code);
return;
}
tsk->thread.error_code = error_code;
tsk->thread.trap_nr = X86_TRAP_GP;
if (show_unhandled_signals && unhandled_signal(tsk, SIGSEGV) &&
printk_ratelimit()) {
pr_info("%s[%d] general protection ip:%lx sp:%lx error:%lx", 👈
tsk->comm, task_pid_nr(tsk), , 👈
regs->ip, regs->sp, error_code); , 👈
print_vma_addr(KERN_CONT " in ", regs->ip); , 👈
pr_cont("\n");
}
force_sig_info(SIGSEGV, SEND_SIG_PRIV, tsk); 🔥
}
NOKPROBE_SYMBOL(do_general_protection);
ここまで来たので一応、確認をとっておくと、IDT = Interrupt Descriptor Table は以下のようなソースになっています。
/arch/x86/entry/entry_64.S
idtentry general_protection do_general_protection has_error_code=1
idtentry page_fault do_page_fault has_error_code=1
abort(3) が HLT 命令を呼び出す訳 —> 「強制」停止 の手段
長くなってきました。一旦、ここまで調べ上げたことをまとめてみましょう
abort(3) は、SIGABRT シグナルや _exit(2) システムコール以外にも、 x86 アーキテクチャでは HLT 命令を用いて特権レベル違反を起こし、カーネルから強制停止する術を利用してプロセスを強制停止する術としているのだと解釈できます。
シグナルでも、システムコールでも停止できないプロセスに対して CPU の例外機構を持ちいて強制停止を試みるのは、ブレーキやエンジンの制御が壊れた車を壁にぶつけるなり海に飛び込むなりして無理やり停止を試みるアクション映画のような比喩を想起させます 🔥🚗
なぜ node プロセスが abort(3) を呼び出すか?
「 abort(3) がなぜ general protection fault を起こすのか？」 を追いかけてきました。 「 なぜ node プロセスが abort(3) を呼び出すか」 がトラブルの根本であり、重要です。
業務上のコンテナの仕様も絡んでおり、公開できる範囲で一般化して記述します。
ざっくり書きだすと
- node プロセスは、シグナルを受けて停止する際に stdio, stdout, stderr の TTY 設定を元に戻す
- node::ResetStdio() 実装されている
- node::ResetStdio() で stdio, stdout, stderr に対して fstat(2) をとる
- この fstat(2) がエラーを返すと、node はアサーション失敗とみなして node::Abort() を呼び出し、さらに libc の abort(3) を呼び出す
という node 側の実装に対して、該当のコンテナは
- コンテナで動いていた node プロセスは、 stdout, stderr に NFS のファイルデスクリプタが関連づいていた
- node プロセス停止のタイミングで、それらの NFS のファイルが NFS サーバ側で前もって削除されてしまっており fstat(2) が ESTALE を返す状況を招いていた
- NFS サーバ側でファイルが削除されると ESTALE を返すのは NFSv3 の挙動に依る*
- NFS のファイルが削除されるのは、該当のサービスでの仕様/挙動であり、意図せず問題を招いてしまっていた。
というところを調べ上げました。まさか NFS が絡んでくるとは …
調査時の gdb, strace
node::ResetStdio() を含むバックトレースは以下のようなものになります。
(gdb) bt
#0 0x00007ffff6d82196 in abort () from target:/lib/x86_64-linux-gnu/libc.so.6
#1 0x0000000000a295f1 in node::Abort() ()
#2 0x0000000000a2965e in node::Assert(node::AssertionInfo const&) ()
#3 0x00000000009f5e60 in node::ResetStdio() ()
#4 0x00000000009f5f8c in node::TrapWebAssemblyOrContinue(int, siginfo_t*, void*) ()
#5 <signal handler called>
#6 0x00007ffff6d82196 in abort () from target:/lib/x86_64-linux-gnu/libc.so.6
#7 0x0000000000a295f1 in node::Abort() ()
#8 0x0000000000a2965e in node::Assert(node::AssertionInfo const&) ()
#9 0x00000000009f5e60 in node::ResetStdio() ()
#10 0x00007ffff6d84ff8 in ?? () from target:/lib/x86_64-linux-gnu/libc.so.6
#11 0x00007ffff6d85045 in exit () from target:/lib/x86_64-linux-gnu/libc.so.6
#12 0x0000000000998567 in node::DefaultProcessExitHandler(node::Environment*, int) ()
#13 0x00000000009cff43 in node::Environment::Exit(int) ()
#14 0x0000000000c0278b in v8::internal::MaybeHandle<v8::internal::Object> v8::internal::(anonymous namespace)::HandleApiCallHelper<false>(v8::internal::Isolate*, v8::internal::Handle<v8::internal::HeapObject>, v8::internal::Handle<v8::internal)
#15 0x0000000000c03d36 in v8::internal::Builtin_Impl_HandleApiCall(v8::internal::BuiltinArguments, v8::internal::Isolate*) ()
#16 0x0000000000c043b6 in v8::internal::Builtin_HandleApiCall(int, unsigned long*, v8::internal::Isolate*) ()
#17 0x00000000013a5b79 in Builtins_CEntry_Return1_DontSaveFPRegs_ArgvOnStack_BuiltinExit ()
#18 0x000000000133e658 in Builtins_InterpreterEntryTrampoline ()
#19 0x00000d97868c0471 in ?? ()
#20 0x00001e96809c2fa9 in ?? ()
#21 0x0000000600000000 in ?? ()
#22 0x00000d97868c0541 in ?? ()
#23 0xffffff8c00000000 in ?? ()
#24 0x00002346432c09f1 in ?? ()
#25 0x00000d97868c0471 in ?? ()
また、以下は node::ResetStdio() が fstat(2) でエラーを返し、Assertion に失敗する際の strace です。
[pid 21923] 22:24:15 +++ exited with 0 +++
[pid 21875] 22:24:15 <... futex resumed> ) = 0 <0.000599>
[pid 21875] 22:24:15 munmap(0x7ffff654a000, 8392704) = 0 <0.000039>
[pid 21875] 22:24:15 epoll_ctl(3<anon_inode:[eventpoll]>, EPOLL_CTL_ADD, 6<pipe:[1059990718]>, {EPOLLIN, {u32=6, u64=6}}) = 0 <0.000023>
[pid 21875] 22:24:15 epoll_ctl(3<anon_inode:[eventpoll]>, EPOLL_CTL_ADD, 8<anon_inode:[eventfd]>, {EPOLLIN, {u32=8, u64=8}}) = 0 <0.000018>
[pid 21875] 22:24:15 epoll_wait(3<anon_inode:[eventpoll]>, [], 1024, 0) = 0 <0.000020>
[pid 21875] 22:24:15 close(6<pipe:[1059990718]>) = 0 <0.000026>
[pid 21875] 22:24:15 close(7<pipe:[1059990718]>) = 0 <0.000026>
[pid 21875] 22:24:15 close(8<anon_inode:[eventfd]>) = 0 <0.000023>
[pid 21875] 22:24:15 close(3<anon_inode:[eventpoll]>) = 0 <0.000022>
[pid 21875] 22:24:15 fstat(0</dev/null>, {st_mode=S_IFCHR|0666, st_rdev=makedev(1, 3), ...}) = 0 <0.000014>
[pid 21875] 22:24:15 fcntl(0</dev/null>, F_GETFL) = 0x8000 (flags O_RDONLY|O_LARGEFILE) <0.000013>
🔥 [pid 21875] 22:24:15 fstat(1</var/log/container/***/.out>, 0x7fffffffdd70) = -1 ESTALE (Stale file handle) <0.000028>
[pid 21875] 22:24:15 write(2</var/log/container/***/hogehoge.log>, "npm[1]: ../src/node.cc:657:void node::ResetStdio(): Assertion `((*__errno_location ())) == (9)' failed.\n", 104) = -1 ESTALE (Stale file handle) <0.000014>
[pid 21875] 22:24:15 futex(0x7ffff7113110, FUTEX_WAKE_PRIVATE, 2147483647) = 0 <0.000013>
[pid 21875] 22:24:15 futex(0x7ffff7547680, FUTEX_WAKE_PRIVATE, 2147483647) = 0 <0.000013>
[pid 21875] 22:24:15 write(2</var/log/container/***/hogehoge.log>, " 1: 0xa295e0 node::Abort() [npm]\n", 33) = -1 ESTALE (Stale file handle) <0.000013>
[pid 21875] 22:24:15 write(2</var/log/container/***/hogehoge.log>, " 2: 0xa2965e [npm]\n", 20) = -1 ESTALE (Stale file handle) <0.000013>
[pid 21875] 22:24:15 write(2</var/log/container/***/hogehoge.log>, " 3: 0x9f5e60 node::ResetStdio() [npm]\n", 38) = -1 ESTALE (Stale file handle) <0.000021>
[pid 21875] 22:24:15 write(2</var/log/container/***/hogehoge.log>, " 4: 0x7ffff6d84ff8 [/lib/x86_64-linux-gnu/libc.so.6]\n", 54) = -1 ESTALE (Stale file handle) <0.000014>
[pid 21875] 22:24:15 write(2</var/log/container/***/hogehoge.log>, " 5: 0x7ffff6d85045 [/lib/x86_64-linux-gnu/libc.so.6]\n", 54) = -1 ESTALE (Stale file handle) <0.000023>
[pid 21875] 22:24:15 write(2</var/log/container/***/hogehoge.log>, " 6: 0x998567 [npm]\n", 20) = -1 ESTALE (Stale file handle) <0.000013>
[pid 21875] 22:24:15 write(2</var/log/container/***/hogehoge.log>, " 7: 0x9cff43 node::Environment::Exit(int) [npm]\n", 48) = -1 ESTALE (Stale file handle) <0.000022>
[pid 21875] 22:24:15 write(2</var/log/container/***/hogehoge.log>, " 8: 0xc0278b [npm]\n", 20) = -1 ESTALE (Stale file handle) <0.000038>
[pid 21875] 22:24:15 write(2</var/log/container/***/hogehoge.log>, " 9: 0xc03d36 [npm]\n", 20) = -1 ESTALE (Stale file handle) <0.000016>
[pid 21875] 22:24:15 write(2</var/log/container/***/hogehoge.log>, "10: 0xc043b6 v8::internal::Builtin_HandleApiCall(int, unsigned long*, v8::internal::Isolate*) [npm]\n", 100) = -1 ESTALE (Stale file handle) <0.000017>
[pid 21875] 22:24:15 write(2</var/log/container/***/hogehoge.log>, "11: 0x13a5b79 [npm]\n", 21) = -1 ESTALE (Stale file handle) <0.000016>
[pid 21875] 22:24:15 rt_sigprocmask(SIG_UNBLOCK, [ABRT], NULL, 8) = 0 <0.000013>
[pid 21875] 22:24:15 tgkill(1, 1, SIGABRT) = 0 <0.000025>
[pid 21875] 22:24:15 --- SIGABRT {si_signo=SIGABRT, si_code=SI_TKILL, si_pid=1, si_uid=1000} ---
💡一部 パス名を改変、マスクをかけています
fstat(2) が ESTALE を返していますね
[pid 21875] 22:24:15 fstat(1</var/log/container/***/.out>, 0x7fffffffdd70) = -1 ESTALE
メモ
node::ResetStdio() に関係する実装は下記のソースになります。
node の実装を追う調査をヘルプしてくれた id:mrtc0 に感謝しています。
調査の終了/サービス担当者へのフィードバック
さて、ここまで調べ上げたことを担当のサービスの技術者、ならびにコンテナを実装した技術者 ( @udzura ) にフィードバックを返しました。
そして、よくよく話を伺ってみると、実は サービスの監視のために定期的に稼働していたコンテナ であり、dmesg のログを出している以外は 特に問題になっていなかったというオチが付きました ( ͡° ͜ʖ ͡°)
補足的な内容
ここまでの流れで拾いきれなかったトピックについても付記しておきます。
補足(1) Haconiwa での問題? 他のコンテナランタイムではどうか?
この項だけ作者の @udzura より補足します。
まず、Haconiwaを利用して立ち上げたコンテナ内部の PID = 1 のプロセスは、執筆時現在のバージョンでは以下のような処理の流れでコンテナの fd = 0, 1, 2 をセットします。
fork(2)するhaconiwa.out、haconiwa.errなどログファイルをO_APPEND|O_WRONLYで開くdup2(2)で fd = 1, 2 の示すファイルをそれらのファイルにする（0は/dev/null）- ほかに存在するfdについては
O_CLOEXECを付与する - コンテナのプログラムに
execve(2)する
一方で、例えば runc のような別のコンテナランタイム実装は、コンテナの PID = 1 が直接ファイルをつかむようなことはせず、親プロセスである container-shim などに繋がるpipeを開いた状態でexecveしています。pipeを挟むことで、少なくともfdへのアクセスでESTALEを返すことは回避できるでしょう。
## 3113 はhttpdコンテナのホストで見たルートPIDです:
$ sudo ls -l /proc/3113/fd
total 0
lrwx------ 1 root root 64 Jun 8 14:30 0 -> /dev/null
l-wx------ 1 root root 64 Jun 8 14:30 1 -> pipe:[26286]
l-wx------ 1 root root 64 Jun 8 14:30 2 -> pipe:[26287]
lrwx------ 1 root root 64 Jun 8 14:30 3 -> socket:[28179]
lr-x------ 1 root root 64 Jun 8 14:30 4 -> pipe:[28195]
l-wx------ 1 root root 64 Jun 8 14:30 5 -> pipe:[28195]
l-wx------ 1 root root 64 Jun 8 14:30 6 -> pipe:[26286]
Haconiwa側でも、直接コンテナの PID = 1 がファイルをつかむ実装を回避する方向で開発を進めています。
補足(2) Vagrant で追試
本エントリを書き出している間、 @udzura とディスカッションをして 改めて問題の再現をとり挙動を調べ直しました
明らかになっていなかったこと
node プロセスは、node::Abort() -> abort(3) を呼び出すと raise (SIGABRT) で停止しそうなものですが、なぜか ABORT_INSTRUCTION = HLT 命令の呼び出しに至り、停止しています。この挙動が明らかにできていませんでした。
Vagrant での再現(1)
Vagrant を用いて Ubuntu 18.04 の NFS サーバの VM と NFS クライアントの VM を作り、 NFSv3 で構成することで問題を再現することができました。
Vagrantfile
Vagrant.configure("2") do |config|
config.vm.define 'client' do |c|
c.vm.box = 'bento/ubuntu-18.04'
c.vm.hostname = 'client000'
c.vm.network :private_network, ip:"192.168.100.100"
c.vm.provision "shell", inline: <<-SHELL
apt install -y nfs-common
mkdir -p /mnt/nfs
# mount 192.168.100.200:/var/nfs/exports /mnt/nfs
SHELL
end
config.vm.define 'server' do |c|
c.vm.box = 'bento/ubuntu-18.04'
c.vm.hostname = 'server000'
c.vm.network :private_network, ip:"192.168.100.200"
c.vm.provision "shell", inline: <<-SHELL
apt install -y nfs-kernel-server
mkdir -p /var/nfs/exports
chown nobody.nogroup /var/nfs/exports
echo '/var/nfs/exports 192.168.100.0/24(rw,sync,fsid=0,crossmnt,no_subtree_check,insecure,all_squash)' > /etc/exports
exportfs -ra
SHELL
end
end
再現の手順
1. NFS クライアントでの手順
node のコードは以下のような内容です。sleep するだけのコードを用意します。
var sleep = require('sleep');
sleep.sleep(5);
次に、node の stdout に NFSv3 のファイルをリダイレクトして起動するスクリプトを用意します。
#!/bin/bash
exec 1> /mnt/nfs/stdout.txt
exec node main.js
unshare コマンドを使って node プロセスを起動し PID = 1 で起動します。
sudo unshare -fp --mount-proc ./launch-node.sh
2. NFS サーバ での手順
NFS クライアント側の node 起動と同時に、NFS サーバ側で ファイルを削除します。
sudo rm -rfv /var/nfs/exports/*.txt
3. NFS クライアント での手順
node プロセスが sleep から起床し、プロセスが停止する過程で general protection fault を起こします。
vagrant@client000:~$ sudo unshare -fp --mount-proc ./launch-node.sh
node[1]: ../src/node.cc:599:void node::ResetStdio(): Assertion `((*__errno_location ())) == (9)' failed.
1: 0xa07f90 node::Abort() [node]
2: 0xa0800e [node]
3: 0x9d4b9c node::ResetStdio() [node]
4: 0xa4b3ce node::NodeMainInstance::Run() [node]
5: 0x9d9228 node::Start(int, char**) [node]
6: 0x7f3a912bbb97 __libc_start_main [/lib/x86_64-linux-gnu/libc.so.6]
7: 0x977335 [node]
Segmentation fault
dmesg は下記の通りです。
[ 9705.959202] traps: node[7479] general protection ip:7f3a912da8f0 sp:7ffc7674b740 error:0 in libc-2.27.so[7f3a9129a000+1e7000]
[ 9705.959210] potentially unexpected fatal signal 11.
[ 9705.959212] CPU: 0 PID: 7479 Comm: node Tainted: G OE 4.15.0-29-generic #31-Ubuntu
[ 9705.959213] Hardware name: innotek GmbH VirtualBox/VirtualBox, BIOS VirtualBox 12/01/2006
[ 9705.959216] RIP: 0033:0x7f3a912da8f0
[ 9705.959216] RSP: 002b:00007ffc7674b740 EFLAGS: 00010246
[ 9705.959218] RAX: 0000000000000004 RBX: 0000000001e12cd0 RCX: 0000000000000000
[ 9705.959219] RDX: 0000000000000000 RSI: 00007ffc7674b620 RDI: 0000000000000002
[ 9705.959220] RBP: 00007ffc7674b870 R08: 0000000000000000 R09: 00007ffc7674b620
[ 9705.959220] R10: 0000000000000008 R11: 0000000000000246 R12: 0000000000000001
[ 9705.959221] R13: 0000000002c8dd58 R14: 84bda12f684bda13 R15: 0000000002c8dd18
[ 9705.959222] FS: 00007f3a92605780(0000) GS:ffff8f1f7fc00000(0000) knlGS:0000000000000000
[ 9705.959223] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 9705.959224] CR2: 000000000286496c CR3: 0000000038a60005 CR4: 00000000000606f0
node プロセスが PID = 1 !
引き続き、再現をとりながら社内の Slack #kernel チャンネルでディスカッションを続けていたところ、以下の資料に辿り着きました。
- Docker で node.js を動かすときは PID 1 にしてはいけない - ngzmのブログ
- PID1 は、カーネルから 特別扱いされてるって本当ですか？ - Kazuki Suda / Docker Meetup Tokyo #6
これを読み、namespace を切って PID 1 で動かした場合に、abort(3) の general protection fault を招く挙動になるのでは? と閃きました
abort(3) の実装は、SIGABRT のシグナルハンドラをクリアしてから自プロセスに kill(2) + SIGABRT を飛ばして停止を試みます。namespace 内の PID 1 のプロセスとして動いている場合は SIGABRT が無視されることになり、ABORT_INSTRUCTION = HLT 命令で停止を試みるステージに達すると考えられます。
Vagrant での再現(2)
node プロセスと NFS を切りはなして、ただ単に abort するだけのコードを用意して再現を試みます。
#include <stdlib.h>
void main() {
abort();
}
これを sudo -f unshare -fp --mount-proc ./abort で unshare して pid = 1 として実行すると再現がとれます。
Jun 9 14:17:34 client000 kernel: [17269.995167] traps: a.out[7613] general protection ip:7f6bfe6ac8f0 sp:7ffcffdd5430 error:0 in libc-2.27.so[7f6bfe66c000+1e7000]
Jun 9 14:17:34 client000 kernel: [17269.995173] potentially unexpected fatal signal 11.
Jun 9 14:17:34 client000 kernel: [17269.995175] CPU: 0 PID: 7613 Comm: a.out Tainted: G OE 4.15.0-29-generic #31-Ubuntu
Jun 9 14:17:34 client000 kernel: [17269.995175] Hardware name: innotek GmbH VirtualBox/VirtualBox, BIOS VirtualBox 12/01/2006
Jun 9 14:17:34 client000 kernel: [17269.995178] RIP: 0033:0x7f6bfe6ac8f0
Jun 9 14:17:34 client000 kernel: [17269.995178] RSP: 002b:00007ffcffdd5430 EFLAGS: 00010246
Jun 9 14:17:34 client000 kernel: [17269.995179] RAX: 0000000000000004 RBX: 0000000000000000 RCX: 0000000000000000
Jun 9 14:17:34 client000 kernel: [17269.995180] RDX: 0000000000000000 RSI: 00007ffcffdd5310 RDI: 0000000000000002
Jun 9 14:17:34 client000 kernel: [17269.995181] RBP: 00007ffcffdd5560 R08: 0000000000000000 R09: 00007ffcffdd5310
Jun 9 14:17:34 client000 kernel: [17269.995181] R10: 0000000000000008 R11: 0000000000000246 R12: 000055c5be03e540
Jun 9 14:17:34 client000 kernel: [17269.995182] R13: 00007ffcffdd5640 R14: 0000000000000000 R15: 0000000000000000
Jun 9 14:17:34 client000 kernel: [17269.995183] FS: 00007f6bfec7b4c0(0000) GS:ffff8f1f7fc00000(0000) knlGS:0000000000000000
Jun 9 14:17:34 client000 kernel: [17269.995184] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Jun 9 14:17:34 client000 kernel: [17269.995184] CR2: 000055691ff61180 CR3: 000000003b37e006 CR4: 00000000000606f0
今回追いかけてきた abort(3) が general protection fault を起こす最小の再現 です。
コアを採取して gdb でソースを確かめます。107行目は ABORT_INSTRUCTION の呼び出しで、確かに合っていそうです。
(gdb) bt
#0 __GI_abort () at abort.c:107
#1 0x00005581f8728653 in main ()
96 /* Try again. */
97 if (stage == 3)
98 {
99 ++stage;
100 raise (SIGABRT);
101 }
102
103 /* Now try to abort using the system specific command. */
104 if (stage == 4)
105 {
106 ++stage;
107 ABORT_INSTRUCTION; 👈
108 }
109
( unshare で起動したバイナリのシンボルを gdb で解決できないのはなぜだろうな ? … )
まとめ
node プロセスが起こした general protection fault を端緒に、abort(3) の実装からカーネル、CPU、コンテナまで潜り込み、トラブルを追いかけた事例を紹介しました。node , NFSv3, コンテナ (pid namespace), abort(3) の実装と、いろいろな要素が合体したキメラのような問題でした。
本エントリのようなトラブルシューティングでは、各種ツールを組み合わせてプロセスの挙動を探り、エビデンスとなるログやトレースをとり、ソースやドキュメントを読み、再現をとり、挙動の裏付けをとり、という地道な作業の積み重ねで問題を打開します。すんなりと問題に至れたようですが、泥くさい手作業での調査や検証でもかなりの時間を費やしています。
本エントリを読んだ方に「こんなツールあるんだ」「こういう挙動は知らなかった」「もっといい方法あるよ」「ここ、もっと調べて欲しい」 と何かしらの感想を喚起できればと思います。
謝辞
本エントリの pull request レビューで、不明瞭だった点にツッコミをいれて最後の詰めを促してくれてた @udzura さんに感謝します。
リンク・リファレンス
- haconiwa/haconiwa
- linuxjm.osdn.jp abort(3)
- IA-32 インテル® アーキテクチャ ソフトウェア・デベロッパーズ・ マニュアル 中巻 A: 命令セット・リファレンス A-M
- IA-32 インテル® アーキテクチャ ソフトウェア・デベロッパーズ・ マニュアル 下巻: システム・プログラミング・ガイド
- node.js - node::ResetStdio()
- Haconiwaでのコンテナのfd開き直しの実装箇所
- Ubuntu Linux 18.04 LTSで、NFSの設定を行う - kazuhira-r.hatenablog.com
- Docker で node.js を動かすときは PID 1 にしてはいけない - ngzmのブログ
- PID1 は、カーネルから 特別扱いされてるって本当ですか？ - Kazuki Suda / Docker Meetup Tokyo #6
- NFS Coding HOWTO - Timo Sirainen