【Vol2. 原因分析】 CentOS7 で glibc をアップデート後、 mod_php + httpd の logrotate (reload ) が失敗する: /lib64/libresolv.so.2: symbol __h_errno, version GLIBC_PRIVATE not defined in file libc.so.6 with link time reference

hiboma.hatenadiary.jp

の続き。

本エントリのサマリ

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

...

httpdetc/httpd/modules/libphp5.so を dleopen(3) して、ld.so が依存の共有ライブラリを解決していく

時系列の整頓

調べたことを時系列に起こす

1. httpd + mod_php が起動している

f:id:hiboma:20190201123743p:plain

2. glibc をアップデートする

httpd古い glibc を参照し続ける

f:id:hiboma:20190201123805p:plain

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 となる

f:id:hiboma:20190201123823p:plain

ということだろうか? とアタリをつけた

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 が最初にそれを指摘してくれていたのだがスルーしてしまった)
  • 特殊な条件が重なって怒るので「バグ」とも言えない、びみょーな不具合だなぁ