(解決済み) DBIx::TransactionManager + File::RotateLogsで意図せずトランザクションが終了してしまう件

DBIx::TransactionManager 1.13で子プロセスでrollbackを実行しないような変更が入っています。

https://metacpan.org/release/NEKOKAK/DBIx-TransactionManager-1.13

TengやDBIx::Sunnyなどでトランザクションを使用し、File::RotateLogsでログを書き出している場合はバージョンアップをお勧めします。

経緯など

某サービスにおいて、DBIx::TransactionManagerを使ってトランザクションを実行している箇所で9時にトランザクションが意図せず終了するという問題がありました。

コードにするとこんな感じ

my $rotatelogs = File::RotateLogs->new(
    logfile => '/path/to/access_log.%Y%m%d%H%M',
    linkname => '/path/to/access_log',
    rotationtime => 86400,
    maxage => 86400*14,
);

my $tm = DBIx::TransactionManager->new($dbh);
my $txn = $tm->txn_scope;

$dbh->do("insert into foo (id, var) values (1,'baz')");

$rotatelogs->print("log! log! log!");

$dbh->do("update foo set var='woody' where id=1");
$txn->commit;

DBIx::TransactionManager->txn_scopeすると、トランザクションを開始し、guardオブジェクトが返ります。commitせずに途中で終了した場合は、guradオブジェクトが破棄され、自動でrollbackがかかる仕組みになっています。

このトランザクション中にログを書くだけなら問題なさそうですが、File::RotateLogsはrotationtimeで設定した時間ごとにファイルを切り替え、maxageよりも古いログがあればProc::Daemonモジュール使い、削除用プロセスをデーモンとして起動して、古いログを削除します。

この際、Proc::Daemonはforkを2回して、プロセスを元のプロセスから切り離しますが、1回目にforkされた子プロセスは孫プロセスをforkしたあとすぐにexit()します。そこで、global destructionが走り、$txn も破棄されるので、なんとrollbackが走ってしまいます。

File::RotateLogsのprintとProc::Daemonを展開するとこんな感じ

$fh->print($log);
if ( 削除するファイルがある ) {
    my $pid = fork; #1回目のfork
    if ( $pid == 0 ) {
        #子プロセス
        $pid = fork; #2回目のfork
        if ( $pid == 0 ) {
            #孫プロセス
            unlink .. #削除
            POSIX::_exit(); #ここはglobal destructionを防いでいた 
        }
        exit; ここでrollback 
    }
    waitpid($pid,0);
}

トランザクション中にforkなんて普通はしないと思いますが、今回はDBIx::TransactionManagerの方で対策をいれてもらい、guardオブジェクトのDESTROYの中で、トランザクション開始時のpidと現在のpidが異なっていたらrollbackせずにそのまま終了するようになりました。

nekokakさんありがとうございます

参考

DBIとforkの関係 - heboi blog
http://nihen.hatenablog.com/entry/2011/11/17/102557