おれがsudoできないのはどう考えてもmetalogが悪い話

Linux

最近、"sudo emerge" などしようとするとその時点で動きが止まってしまうことが多々あってまーたbtrfsか?と思っていました。でも、psを見てもSTATEは"D"になってないし、btrfsぽくはない。そんなある日metalogを強制終了してやると、止まっていたsudoが動きだすことに気がついたのです。さて、いったいmetalogがなにがどーしてsudoを止めているのかな?

こういう状況の時

  • metalogの下にconsolelog.shがゾンビになってたくさんぶらさがっている
  • metalogのmasterプロセスをstraceするとwriteの途中で止まっている
  • gdbでmetalogのmasterプロセスをbacktraceするとmetalog.cのsignal_doLog_queue()で止まっている

ことがわかります

signal_doLog_queue() はこうなっていて、ここのwriteで停止しています。

static void signal_doLog_queue(const char *fmt, const unsigned int pid, const int status)
{
    ssize_t ret;
    unsigned int fmt_len = (unsigned int)strlen(fmt);
    char buf[sizeof(pid) + sizeof(status) + sizeof(fmt_len)];
    memcpy(buf, &pid, sizeof(pid));
    memcpy(buf+sizeof(pid), &status, sizeof(status));
    memcpy(buf+sizeof(pid)+sizeof(status), &fmt_len, sizeof(fmt_len));
    ret = write(dolog_queue[1], buf, sizeof(buf));
    assert(ret == sizeof(buf));
    ret = write(dolog_queue[1], fmt, fmt_len);
    assert(ret == fmt_len);
}

ここでwriteされているdolog_queueは、このようにsocketかpipeになっています。

    /* setup the signal handler pipe */
    if (socketpair(AF_LOCAL, SOCK_STREAM, 0, dolog_queue) < 0) {
        if (pipe(dolog_queue) < 0) {
            warnp("Unable to create a pipe");
            return -4;
        }
    }

すると読みだしは誰なんだ?というのが気になるところで、読みだしているのは、このmetalogのメイン関数であるprocess()になっています

static int process(const int sockets[])
{
...
    siglog = syslog = klog = NULL;
    nfds = 0;

    siglog = &fds[nfds];
    fds[nfds].fd = dolog_queue[0];
    fds[nfds].events = POLLIN | POLLERR | POLLHUP | POLLNVAL;
    fds[nfds].revents = 0;
...
    for (;;) {
        while (poll(fds, nfds, -1) < 0 && errno == EINTR)
            ;

        /* Signal queue */
        if (siglog && siglog->revents) {
            event = siglog->revents;
            siglog->revents = 0;
            if (event != POLLIN) {
                warn("Signal queue socket error - aborting");
                close(siglog->fd);
                return -1;
            }

            signal_doLog_dequeue();
        }

こんな感じでpollで読めるfdを見つけて読むという単純なやつですね。 問題になるのが、socketなりpipeなりを自分で読んで自分で書いてます。だから、socketなりのバッファがいっぱいになると相手が読み出してくれるまで待つのだけれど、その読む相手というのがwriteで待っている自分なわけで完全にmetalogが停止してしまう、というわけですよ。(具体的にsocketのバッファサイズを調べたりしたかったがうまくいかず)

さて、じゃあなんでそんなにいっぱいになるほどwriteされてるのか?という問題に入ります。

signal_doLog_queue()はもともと、 SIGCHLDのシグナルハンドラである sigchld(int sig)から、子プロセスが0以外の終了ステータスとなった時に呼ばれている関数です。つまり、最初に書いていた consolelog.shが0以外の返り値で死んだ場合にログが書かれています。

consolelog.shはたったこれだけでエラーになりそうなのは evalの書きこみのところだけですね。

#!/bin/sh
# consolelog.sh
# For metalog -- log to a console

set -f

. /etc/conf.d/metalog
if [ -z "${CONSOLE}" ] ; then
	CONSOLE="/dev/console"
fi

if [ -z "${FORMAT}" ] ; then
	FORMAT='$1 [$2] $3'
fi

for d in ${CONSOLE} ; do
	eval echo ${FORMAT} > ${d}
done

exit 0

"while : ;do echo foo > /dev/tty10;done"などと書いたスクリプトを大量に実行してみるとIOエラーがすぐに出てエラーで死んでくることがわかるかと思います。

結局のところまとめると

  • btrfsが大量にWARNを発生
  • metalogがそれをconsolelog.shを使って書こうとする
  • 同時に書こうとするのでコンソールがIOエラー
  • 多くのconsolelog.shが0以外のステータスで終了
  • シグナルハンドラでsocketに書こうとするがバッファがいっぱいで読みだされるまで止まる
  • writeで止まっているから読みだし側の処理が行なわれない

こんなことがmetalogで起こっている。 大量のログ書きこみ自体は手元でloggerでやろうとしてもうまくいかないので、なかなか再現できない。

sudoできなくなるのはとてもつらいので、別のloggerに乗り換えようかな。