dovecotが動かない？

ちょっとした作業の合間にMySQLを5.1.x系にアップデートしてみたんですが、そうしたらなぜかdovecotがうまく動かなくなってしまいました。と、言っても起動できないわけではなく、正しいユーザ名とパスワードで認証しようとすると認証プロセスが落ちてしまうといった感じ。

dovecot: child 807 (auth) killed with signal 11

ログはこれしか残らないのでとりあえずdovecotのサイトで似たような事象がないかどうか調べてみたものの、どの事象ともいまいち合致しなかったのですが、BugreportsページのDebugging crashesにgdbを使ったバックトレースの取り方が解説されていました。

Debugging crashes

Whenever Dovecot crashes, you see something like this in log file:
dovecot: Apr 23 11:16:05 Error: child 86116 (imap) killed with signal 11
No matter how that happened, it s a bug and will be fixed if you can provide enough information on how it happened. Best way is to get backtrace from gdb, but the problem is that Dovecot doesn t dump core files by default.

僕はdovecotのコードの中身はほとんど知らないのと、gdbというかコマンドラインのデバッガを使うのは前の会社の新入社員研修以来だったので、ダメもとでバックトレースだけ取ってみることにしました。

† gdbでプロセスをトレースしてみる

とりあえず、落ちるのは認証をかけたときなので普通に起動させておいて起動してた認証プロセスをgdbでトレースしてみました。
リファレンスを見るとたくさんコマンドがあるのですが、僕は簡単なコマンドしか知らないので使っているはこれだけです。

・b (breakpoint) ブレークポイント設定。プログラムを停止させる場所を表示する
・c (continue) 次のブレークポイントまで実行する。クラッシュしたらそこで停止する
・p (print) 変数の内容を表示する
・bt (backtrace) バックトレースを表示する

以下、本当にデバッグ画面なのでこういうの見慣れない人は読み飛ばしてください。

# gdb attach 14730
GNU gdb Red Hat Linux (6.1post-1.20040607.43.0.1rh)
Copyright 2004 Free Software Foundation, Inc.
GDB is free software, covered by the GNU General Public License, and you are
welcome to change it and/or distribute copies of it under certain conditions.
Type "show copying" to see the conditions.
There is absolutely no warranty for GDB.  Type "show warranty" for details.
This GDB was configured as "i386-redhat-linux-gnu"...attach: そのようなファイルやディレクトリはありません.

Attaching to process 14730
Reading symbols from /usr/libexec/dovecot/dovecot-auth...Reading symbols from /usr/lib/debug/usr/libexec/dovecot/dovecot-auth.debug...
done.
Using host libthread_db library "/lib/tls/libthread_db.so.1".
done.
Reading symbols from /lib/libpam.so.0...done.
Loaded symbols for /lib/libpam.so.0
Reading symbols from /usr/lib/libgssapi_krb5.so.2...done.
Loaded symbols for /usr/lib/libgssapi_krb5.so.2
Reading symbols from /usr/lib/libkrb5.so.3...done.
Loaded symbols for /usr/lib/libkrb5.so.3
Reading symbols from /usr/lib/libk5crypto.so.3...done.
Loaded symbols for /usr/lib/libk5crypto.so.3
Reading symbols from /lib/libcom_err.so.2...done.
Loaded symbols for /lib/libcom_err.so.2
Reading symbols from /lib/libresolv.so.2...done.
Loaded symbols for /lib/libresolv.so.2
Reading symbols from /lib/libcrypt.so.1...done.
Loaded symbols for /lib/libcrypt.so.1
Reading symbols from /lib/libdl.so.2...done.
Loaded symbols for /lib/libdl.so.2
Reading symbols from /lib/tls/libc.so.6...done.
Loaded symbols for /lib/tls/libc.so.6
Reading symbols from /lib/ld-linux.so.2...done.
Loaded symbols for /lib/ld-linux.so.2
Reading symbols from /usr/lib/dovecot/auth/vpopmail.so...done.
Loaded symbols for /usr/lib/dovecot/auth/vpopmail.so
0x00b637a2 in _dl_sysinfo_int80 () from /lib/ld-linux.so.2
(gdb) c
Continuing.

Program received signal SIGSEGV, Segmentation fault.
auth_request_userdb_callback (result=158689672, reply=0x97568a0, request=0x8086006) at auth-request.c:590
590             struct userdb_module *userdb = request->userdb->userdb;
(gdb) p request->userdb->userdb
Cannot access memory at address 0x6b6f3460
(gdb) bt
#0  auth_request_userdb_callback (result=158689672, reply=0x97568a0, request=0x8086006) at auth-request.c:590
#1  0x003ce5d3 in vpopmail_lookup () from /usr/lib/dovecot/auth/vpopmail.so
#2  0x080548b8 in auth_request_lookup_user (request=0x97568a0, callback=0x6b6f3450) at auth-request.c:658
#3  0x08055ddd in auth_request_userdb_callback (result=USERDB_RESULT_USER_UNKNOWN, reply=0x0, request=0x97568a0) at auth-request.c:598
#4  0x080604bb in passwd_lookup (auth_request=0x97568a0, callback=0x8055d9e <auth_request_userdb_callback>) at userdb-passwd.c:43
#5  0x080548b8 in auth_request_lookup_user (request=0x97568a0, callback=0x6b6f3450) at auth-request.c:658
#6  0x08056c71 in auth_request_handler_master_request (handler=0x9755348, master=0x974ed80, id=1, client_id=1)
    at auth-request-handler.c:477
#7  0x080536ac in master_input (context=0x974ed80) at auth-master-connection.c:74
#8  0x08068cf4 in io_loop_handler_run (ioloop=0x974c1a8) at ioloop-epoll.c:203
#9  0x0806811c in io_loop_run (ioloop=0x974c1a8) at ioloop.c:326
#10 0x080596c2 in main (argc=1, argv=0xbfe83364) at main.c:321
(gdb) bt full
#0  auth_request_userdb_callback (result=158689672, reply=0x97568a0, request=0x8086006) at auth-request.c:590
        userdb = Variable "userdb" is not available.
(gdb) quit

これを見るとrequest->userdb->userdbがCannot access memoryとなっているので、プログラムが落ちているのがわかると思います。しかしながら、なぜuserdbが壊れてしまっているのかはこれだけでは残念ながらわかりません。

† へんなsoを読み込んでいる

いい加減諦めようとおもったのですが、ちょっと気になる部分があったのでもうちょっとだけ調べることにしました。このdovecot-authですが、/usr/lib/dovecot/auth/vpopmail.soという変なsoを読み込んでいて、バックトレースを見るとそのsoの中でエラーが発生しているようだったので、このsoが何処から来たのか調べてみました。

# rpm -qf /usr/lib/dovecot/auth/vpopmail.so
ファイル /usr/lib/dovecot/auth/vpopmail.so はどのパッケージにも属していません

orz.....

痛すぎるミスです。というか、こんな超環境依存なバグにはまるのは世界でおそらく僕一人でしょうから、バグレポートなんてあるはずないです。ということで、このsoを削除したところ状況は解決しました。

† 思い出した

dovecotはrpmを作って入れているんですが、以前間違って普通にmake installしてしまったことがあり、そのときにさらに追加モジュールとしてvpopmail.soを別にコンパイルして入れていたことをすっかり失念していました。なぜ今までうまく動いていたのかはかなり謎ですが（単にldconfigしてなかっただけかもしれません）、とにかく解決してよかったです。

まさかこんなことで徹夜になるとは思っていませんでしたけど。(ここで4/1 6:00)