の続き。
本エントリのサマリ
- CentOS7 で httpd + mod_php が起動している
- glibc のアップデートをすると
__h_errnoシンボルが増える - httpd の reload をしても httpd プロセスが古い glibc を参照しつづており、libphp5 -> libresolv.so が依存する
__h_errnoシンボルを解決できない - 結果、httpd が reload 失敗 する
という現象をおった. 以下はその詳細
前回のログを調べ直す
前回のエントリでは下記のログを調べていた
/lib64/libresolv.so.2: symbol __h_errno, version GLIBC_PRIVATE not defined in file libc.so.6 with link time reference
symbol __h_errno が未定義だと言っているので、素直にそのシンボルを調べ直した
__h_errnor のシンボルを調査する
glibc のアップデート前後でシンボルを採取して比較してみたところ、アップデート後に __h_errno のシンボルが増えていた
glibc アップデート前
再現を取った時のバージョンは glibc-2.17-196.el7.x86_64
$ nm /lib64/libresolv.so.2 | grep __h_errno
$ objdump -Tt /lib64/libresolv.so.2 | grep __h_errno
$ nm /lib64/libc.so.6 | grep __h_errno 0000000000110390 t __GI___h_errno_location 0000000000110390 T __h_errno_location
$ objdump -Tt /lib64/libc.so.6 | grep __h_errno 0000000000110390 l F .text 0000000000000011 __GI___h_errno_location 0000000000110390 g F .text 0000000000000011 __h_errno_location 0000000000110390 g DF .text 0000000000000011 GLIBC_2.2.5 __h_errno_location
glibc アップデート後
再現を取った時のバージョンは glibc-2.17-196.el7.x86_64.
$ nm /lib64/libresolv.so.2 | grep __h_errno
U __h_errno@@GLIBC_PRIVATE
$ objdump -Tt /lib64/libresolv.so.2 | grep __h_errno 0000000000000000 *UND* 0000000000000000 __h_errno@@GLIBC_PRIVATE 👈 0000000000000000 D *UND* 0000000000000000 GLIBC_PRIVATE __h_errno 👈
$ nm /lib64/libc.so.6 | grep __h_errno
0000000000117ff0 t __GI___h_errno_location
000000000000008c B __h_errno 👈
0000000000117ff0 T __h_errno_location
$ objdump -Tt /lib64/libc.so.6 | grep __h_errno 0000000000117ff0 l F .text 0000000000000011 __GI___h_errno_location 0000000000117ff0 g F .text 0000000000000011 __h_errno_location 000000000000008c g .tbss 0000000000000004 __h_errno 👈 000000000000008c g D .tbss 0000000000000004 GLIBC_PRIVATE __h_errno 👈 0000000000117ff0 g DF .text 0000000000000011 GLIBC_2.2.5 __h_errno_location
👈 に指した __h_errno が増えている
httpd を起動してる状態で glibc をアップデートすると何が起きるか
httpd を起動してる状態で glibc をアップデートすると何が起きているか? lsof で見るとわかるのだが、httpd は古い libc.so と libresolv.so を参照し続けている
$ sudo lsof -p $(pgrep httpd | head -1) | grep -e libresolv -e libc-2.17 httpd 2843 root DEL REG 253,0 33566307 /usr/lib64/libresolv-2.17.so;5c530fe7 httpd 2843 root DEL REG 253,0 33562151 /usr/lib64/libc-2.17.so;5c530fe7
DEL= ファイルシステムからパスは消えているが、参照カウントが残っているのでファイルの実体は残っている- 古い .so を参照し続けるのは、(確か) RPM が rename(2) で新しい glibc に置き換えるから.
pmap(3) でもよい
mmap(2) している仮想アドレスも把握したいのであれば pmap(3) を使う
$ sudo pmap -p $(pgrep httpd | head -1) | grep -e libresolv -e libc-2.17 00007f193f553000 88K r-x-- /usr/lib64/libresolv-2.17.so;5c530fe7 (deleted) 00007f193f569000 2048K ----- /usr/lib64/libresolv-2.17.so;5c530fe7 (deleted) 00007f193f769000 4K r---- /usr/lib64/libresolv-2.17.so;5c530fe7 (deleted) 00007f193f76a000 4K rw--- /usr/lib64/libresolv-2.17.so;5c530fe7 (deleted) 00007f194b9d3000 1760K r-x-- /usr/lib64/libc-2.17.so;5c530fe7 (deleted) 00007f194bb8b000 2048K ----- /usr/lib64/libc-2.17.so;5c530fe7 (deleted) 00007f194bd8b000 16K r---- /usr/lib64/libc-2.17.so;5c530fe7 (deleted) 00007f194bd8f000 8K rw--- /usr/lib64/libc-2.17.so;5c530fe7 (deleted)
観測: httpd を realod すると?
httpd を reload する際の strace をとると、古い /lib64/libresolv.so.2 や libphp5.so をアンロード ( munmap(2) )し、再度ロードするのが観測できる
アンロードの様子
reload している際に munmap(2) で観測できる
/* strace で munmap だけに絞り込んでいる */ munmap(0x7f67113ac000, 1052672) = 0 munmap(0x7f67114ad000, 266240) = 0 munmap(0x7f671135d000, 323584) = 0 munmap(0x7f6703797000, 6742568) = 0 munmap(0x7f6703305000, 2584736) = 0 munmap(0x7f67030ec000, 2198200) = 0 munmap(0x7f6702d82000, 3575896) = 0
要注意なのが、 httpd の reload 時に glibc はアンロードされないのだ
再ロードの様子
/* strace で open, mmap だけに絞り込んでいる */
16:50:58 open("/etc/httpd/modules/libphp5.so", O_RDONLY|O_CLOEXEC) = 8</usr/lib64/httpd/modules/libphp5.so> <0.000008>
16:50:58 mmap(NULL, 6742568, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 8</usr/lib64/httpd/modules/libphp5.so>, 0) = 0x7fcc710b6000 <0.000007>
16:50:58 mmap(0x7fcc71676000, 606208, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 8</usr/lib64/httpd/modules/libphp5.so>, 0x3c0000) = 0x7fcc71676000 <0.000008>
16:50:58 mmap(0x7fcc7170a000, 107048, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7fcc7170a000 <0.000009>
16:50:58 open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 8</etc/ld.so.cache> <0.000009>
16:50:58 mmap(NULL, 19484, PROT_READ, MAP_PRIVATE, 8</etc/ld.so.cache>, 0) = 0x7fcc7ee1b000 <0.000006>
16:50:58 open("/lib64/libresolv.so.2", O_RDONLY|O_CLOEXEC) = 8</usr/lib64/libresolv-2.17.so> <0.000008>
...
httpd が etc/httpd/modules/libphp5.so を dleopen(3) して、ld.so が依存の共有ライブラリを解決していく
時系列の整頓
調べたことを時系列に起こす
1. httpd + mod_php が起動している
2. glibc をアップデートする
2. httpd を reload する
httpd の親プロセスは pid を変えずに reload を始める
- httpd の親プロセスは 古い glibc を参照したまま
libphp5.soをロードし直す libphp5.soをロードする際に、依存している/lib64/libresolv.so.2をロードする/lib64/libresolv.soをロードする際にsymbol __h_errnoを解決しようとするが、 httpd は古い glibc を参照したまま であり、古い glibc では__h_errnoを解決できない
エラーとして扱われ、上位の httpd 層まで伝播して Syntax Error となる
ということだろうか? とアタリをつけた
LD_DEBUG=symbols,bindings で追いかける
LD_DEBUG オプションの存在を思い出したので、これでデバッグログをとり確認を取った
/* sudo vim /etc/sysconfig/httpd */
LD_DEBUG=symbols,bindings
LD_DEBUG 環境変数をセットして再現をとりなおすと /var/log/httpd/error_log に大量のログがでてくる
2841: symbol=__h_errno; lookup in file=/usr/sbin/httpd [0]
2841: symbol=__h_errno; lookup in file=/lib64/libpcre.so.1 [0]
2841: symbol=__h_errno; lookup in file=/lib64/libselinux.so.1 [0]
2841: symbol=__h_errno; lookup in file=/lib64/libaprutil-1.so.0 [0]
2841: symbol=__h_errno; lookup in file=/lib64/libcrypt.so.1 [0]
2841: symbol=__h_errno; lookup in file=/lib64/libexpat.so.1 [0]
2841: symbol=__h_errno; lookup in file=/lib64/libdb-5.3.so [0]
2841: symbol=__h_errno; lookup in file=/lib64/libapr-1.so.0 [0]
2841: symbol=__h_errno; lookup in file=/lib64/libpthread.so.0 [0]
2841: symbol=__h_errno; lookup in file=/lib64/libdl.so.2 [0]
👉 2841: symbol=__h_errno; lookup in file=/lib64/libc.so.6 [0]
🔥 2841: /lib64/libresolv.so.2: error: relocation error: symbol __h_errno, version GLIBC_PRIVATE not defined in file libc.so.6 with link time reference (fatal)
ダイナミックリンカ? が __h_errno のシンボルを順に探していく様子、 /lib64/libc.so.6 で lookup が失敗しているのがトレースできた
まとめ
- 当初は別のバグを疑ってかかっていて、シンボルを調べることをしなかった ( 同僚である zipper が最初にそれを指摘してくれていたのだがスルーしてしまった)
- 特殊な条件が重なって怒るので「バグ」とも言えない、びみょーな不具合だなぁ
