stdout/stderrはclose()するべからず

デバッグログの出力用にNSLog()は普通に使うものだけど、リリースにあたってこの出力が鬱陶しいなと思う事がある。Console.app(コンソール)で見えてしまうというのもあるし、syslogで言うようなログレベルの設定もできないので、エラー時などに重要な意味を持つログメッセージから、「備えあれば憂い無し」的にたまに必要になるかもしれないときのために出しておくデバッグ情報まで、区別無く一カ所に出てしまうというのはどうしても扱いづらいなと感じるものだ。

そんなこんなで、リリースビルドの際にはNSLog()の出力をデバッグファイルにリダイレクトしてConsole.appには出さないような仕組みをIntermezzoには入れていた。おおむね下記の要領で。

int
redirectlog(const char* appname)
{
    char path[64], env[32], *p;
    time_t t;

    snprintf(path, sizeof(path) - 1, "/tmp/%s.debug.%lu.log", appname, time(&t));
    snprintf(env, sizeof(env) - 1, "%s_DEBUG", appname);
    for (p = env; *p; *p++) {
        *p = toupper(*p);
    }
    
    if (getenv(env)) {
        freopen(path, "w", stderr);
    } else {
        fclose(stderr);
    }
    return 0;
}

さてこれでSnow Leopardになって問題が起こった。Leopard時代にはこれで何事もなかったのだが、あるいは問題は発生していたのに発見できていなかったのだろうか。検証できる環境を無くして(=2台あるMacをともにSnow Leopardに上げて)しまったので、真相はひとまず分からなくなってしまったが。

どんな問題かと言うと、IntermezzoがIRCサーバとの通信を確立した直後にいきなり"Excess Flood"で通信を切断されてしまうのだった。どうも見てみると、ログ出力の内容がそのままIRCサーバに向けて送出されているらしい。何のことはない、IRCサーバとの接続でソケットディスクリプタがstderrがcloseされているために空きとなった2番に入ってしまったのである。NSLog()は仕様に沿ってSTDERR_FILENOすなわち2番に出力しようとするので、大量のログがIRCサーバとの間のソケットに書き出されてしまい、floodingと看做されて切断を余儀なくされたと言う訳だ。

という訳で、fclose()を以下のように置き換えて問題を回避することができた。まああとから考えれば自然なことだし、うんそうだよ普通に気付けよ俺っていうか。残るはLeopardでどうだったのか、ということだけども、うーん。どうなんでしょう。

int
redirectlog(const char* appname)
{
    ....

    if (getenv(env)) {
        freopen(path, "w", stderr);
    } else {
        freopen("/dev/null", "w", stderr);
    }
    return 0;
}