安定運用に入ったepgrecだったが、稀に録画が失敗してしまう。頻度は読めないが、多くても1週間に数回とか。定期性がないので、自分の作業が影響したのかと思ってしまって調査を先延ばしにしていた。録画に失敗すると、rivarunとリアルタイムエンコードしているffmpegのプロセスが残り続けるので、おいおい何かのきっかけで気が付く。特にffmpegのプロセスが厄介で、QSVエンコードを使っているせいか、割り込み不可の待機状態に入ってしまいkillできなくなってしまう。

こうなってしまうと、もはやOS再起動するくらいしか手がなくなるので非常に面倒だ。下手すると、shutdownすらできずに無理矢理リセットするしかなかったりする。それももちろん面倒なんだけど、やはり不定期に録画失敗が起きるのは頂けない。まずは障害が起きた際に、すぐに気付いて調べられるようにしたい。障害時に自分が特別な作業をやっていないことを切り分けられるだけでも意味あるし。何度かの障害を経て、うっすら作業影響でない気はし始めていた。

この問題が起きると、epgrec動作ログに『[予約ID:xxxx 終了化(予約開始失敗・AT[yyyy]無残留)]』みたいなエラーが記録される。プロセスがハングしているから終了処理できないということかな。epgrecでのエラーは珍しく、ほぼこの問題でしか発生しない。そこでエラー発生時にメールを飛ばすような修正を試みる。ぐぐって調べるとpearのMailモジュールを使えばgmailからメールできそう。pearが1.10以上でないと、うまくインストールできなかったので、remi-php55からpearをインストールした。

yum install -y http://rpms.famillecollet.com/enterprise/remi-release-7.rpm
yum install -y --enablerepo=remi-php55 php-pear
pear install Mail Net_SMTP

epgrec動作ログを処理しているのはrecLog.inc.phpなので、ここにrecmail()ファンクションを追加する。そして、それをreclog()ファンクションから呼び出すように修正する。以下のような感じ。

vi recLog.inc.php
    :
<?php
require_once "Mail.php";
    :
function reclog( $message , $level = E_INFO ) {
        try {
                if($level == EPGREC_ERROR)
                        recmail($message);
    :
function recmail($message) {

        $rcptto = "xxxx@docomo.ne.jp";
        $mailfrom = "yyyy@gmail.com";

        $params = array(
                "host" => "smtp.gmail.com",
                "port" => 587,
                "auth" => true,
                "username" => $mailfrom,
                "password" => "xxxxxxxx"
        );
        $mailObject = Mail::factory("smtp", $params);

        $headers = array(
                "To" => $rcptto,
                "From" => $mailfrom,
                "Subject" => 'epgrec error',
                "Content-Type" => 'text/plain; charset=iso-2022-jp',
                "Content-Transfer-Encoding" => '7bit',
        );
        $message = mb_convert_encoding($message, "ISO-2022-JP", "auto");
        $mail = $mailObject -> send($rcptto, $headers, $message);

        if (PEAR::isError($mail)) {
                echo($mail->getMessage());
        }
}
?>

これでエラー時にメールが飛んでくるようになったので障害調査が捗る。何度かの障害から類推すると、やはり自分の作業影響という可能性は低そう。OSやらnginxやらphpなど、あらゆるログを追いかけてみる。なかなかそれらしき問題が見つからない。そうだ、mirakurunを忘れていた。mirakurunこそ、もっとも怪しいコンポーネントだった。そのログを追っていくと、問題の時間帯に気になるエラーが記録されていた。

less /usr/local/var/log/mirakurun.stderr.log
    :
2017-06-09T00:31:32.229+09:00 warn: TSFilter is overflowing the buffer...
2017-06-09T00:32:02.230+09:00 error: TSFilter will closing because reached time limit of overflowing the buffer...

TSFilterのbufferが枯渇して強制的にcloseされている。メッセージ文字列からソースを確認してみると、/usr/lib/node_modules/mirakurun/lib/Mirakurun/TSFilter.js というところで処理されていた。どうやらstream.Duplexを継承したTSFilterクラスの_write()メソッドにおける問題。うんうん、なるほど！なんて、node.js見たことないんだよなあ。。。次回、バッファ枯渇問題をまじめに追ってみようと思います。