monologでPHPのFatalエラーをログに残す

php monolog

この記事はSymfony Advent Calendar 2014の9日目の記事です。

昨日は おかぽんさんの SymfonyのDIを利用してMail送信クラスをインテグレーションテストする：コード編 でした

Symfony のエラーハンドリングはとても優秀 (ただし2.4以降)

Symfony は monolog が標準でバンドルされており、2.4からはエラーハンドリングをFWでとても良い感じにやってくれます。

Symfony 2.4以降の devで Noticeエラー

たとえば、dev環境だと

<?php

namespace AppBundle\Controller;

use Sensio\Bundle\FrameworkExtraBundle\Configuration\Route;
use Symfony\Bundle\FrameworkBundle\Controller\Controller;

class DefaultController extends Controller
{
    /**
     * @Route("/", name="homepage")
     */
    public function indexAction()
    {
        echo $a;
        return $this->render('default/index.html.twig');
    }
}

のような未定義の変数を書いてしまった場合のようなNoticeのエラー時には次のようなデバッグ画面で教えてくれます。

そして、app/logs/dev.logには

[2014-12-09 00:01:57] request.CRITICAL: Uncaught PHP Exception Symfony\Component\Debug\Exception\ContextErrorException: "Notice: Undefined variable: a" at /private/var/www/sf-sample/src/AppBundle/Controller/DefaultController.php line 15 {"exception":"[object] (Symfony\\Component\\Debug\\Exception\\ContextErrorException: Notice: Undefined variable: a at /private/var/www/sf-sample/src/AppBundle/Controller/DefaultController.php:15)"} []

といった内容のログが残ります。便利です。

Symfony 2.4以降の devで Fatal エラー

また、Fatalエラーが起こるような次のような Syntax Error の場合でも

<?php

namespace AppBundle\Controller;

use Sensio\Bundle\FrameworkExtraBundle\Configuration\Route;
use Symfony\Bundle\FrameworkBundle\Controller\Controller;

class DefaultController extends Controller
{
    /**
     * @Route("/", name="homepage")
     */
    public function indexAction()
    {
        echo
        return $this->render('default/index.html.twig');
    }
}

次のようなデバッグ画面で教えてくれ、

dev.logにも

[2014-12-09 00:05:52] request.CRITICAL: Uncaught PHP Exception Symfony\Component\Debug\Exception\FatalErrorException: "Parse Error: syntax error, unexpected 'return' (T_RETURN)" at /private/var/www/sf-sample/src/AppBundle/Controller/DefaultController.php line 16 {"exception":"[object] (Symfony\\Component\\Debug\\Exception\\FatalErrorException: Parse Error: syntax error, unexpected 'return' (T_RETURN) at /private/var/www/sf-sample/src/AppBundle/Controller/DefaultController.php:16)"} []

といったように教えてくれます。

Symfony 2.4以降の prodで Noticeエラー

ただ、面倒なのが本番(prod)環境のときです。まず、前提として php.ini で

display_errors = Off

と設定されていて、たとえば nginx で

server {
...
error_log /usr/local/var/log/nginx/project_error.log;
...
}

となっているとします。
(本番環境でdisplay_errors = On なんてことないですよね)

この状態でNoticeエラーを起こしてみるとエラーは表示されず、何事もないかのように処理がおこなわれました。
そして、logs/prod.log をみてもエラーは記録されていません。
その代わりに project_error.log 側にphp-fpmからのエラーが記録されました。

2014/12/09 00:10:33 [error] 1737#0: *27 FastCGI sent in stderr: "PHP message: PHP Notice: Undefined variable: a in /private/var/www/sf-sample/src/AppBundle/Controller/DefaultController.php on line 15" while reading response header from upstream, client: 127.0.0.1, server: sf.localhost, request: "GET / HTTP/1.1", upstream: "fastcgi://127.0.0.1:9054", host: "sf.localhost:9191"

つまり、Noticeエラーは標準ではアプリケーションのログには出ないので忘れずに設定したエラー出力先を監視する必要があります。

Symfony 2.4以降の prod で Fatal エラー

また、fatalエラーを起こしてみます。本番環境なのでエラーページが表示されました。

こちらは、アプリケーションのログ (prod.log)にも記録されています。

[2014-12-09 00:12:07] php.EMERGENCY: Fatal Parse Error: syntax error, unexpected 'return' (T_RETURN) {"type":1,"file":"/private/var/www/sf-sample/src/AppBundle/Controller/DefaultController.php","line":16,"level":32767,"stack":}
[2014-12-09 00:12:07] request.CRITICAL: Uncaught PHP Exception Symfony\Component\Debug\Exception\FatalErrorException: "Parse Error: syntax error, unexpected 'return' (T_RETURN)" at /private/var/www/sf-sample/src/AppBundle/Controller/DefaultController.php line 16 {"exception":"[object] (Symfony\\Component\\Debug\\Exception\\FatalErrorException: Parse Error: syntax error, unexpected 'return' (T_RETURN) at /private/var/www/sf-sample/src/AppBundle/Controller/DefaultController.php:16)"} []

monolog は メモリ不足のエラーもログに残してくれる

そして、偉いのはメモリ不足時のエラーもちゃんと記録します。

[2014-12-09 00:16:23] php.EMERGENCY: Fatal Error: Allowed memory size of 134217728 bytes exhausted (tried to allocate 100000000000000001 bytes) {"type":1,"file":"/private/var/www/sf-sample/src/AppBundle/Controller/DefaultController.php","line":15,"level":32767,"stack":}
[2014-12-09 00:16:23] request.CRITICAL: Uncaught PHP Exception Symfony\Component\Debug\Exception\OutOfMemoryException: "Error: Allowed memory size of 134217728 bytes exhausted (tried to allocate 100000000000000001 bytes)" at /private/var/www/sf-sample/src/AppBundle/Controller/DefaultController.php line 15 {"exception":"[object] (Symfony\\Component\\Debug\\Exception\\OutOfMemoryException: Error: Allowed memory size of 134217728 bytes exhausted (tried to allocate 100000000000000001 bytes) at /private/var/www/sf-sample/src/AppBundle/Controller/DefaultController.php:15)"} []

なぜ偉いかというと、メモリ不足エラーが発生した時点からログに書きだそうとしても、既にメモリ不足状態なので書き出すことはできない可能性があります。が、monologはとりあえずログを書き出すメモリ分を確保しておいてから処理を行い、エラー時にはその確保したメモリを開放して書き込んでいるようです。

https://github.com/Seldaek/monolog/blob/master/src/Monolog/ErrorHandler.php#L94

<?php
...
    public function registerFatalHandler($level = null, $reservedMemorySize = 20)
    {
        register_shutdown_function(array($this, 'handleFatalError'));
        $this->reservedMemory = str_repeat(' ', 1024 * $reservedMemorySize); // ここで事前に確保
        $this->fatalLevel = $level;
    }
...
    public function handleFatalError()
    {
        $this->reservedMemory = null; // エラーを書き込む前に領域開放
        $lastError = error_get_last();
        if ($lastError && in_array($lastError['type'], self::$fatalErrors)) {
            $this->logger->log(
                $this->fatalLevel === null ? LogLevel::ALERT : $this->fatalLevel,
                'Fatal Error ('.self::codeToString($lastError['type']).'): '.$lastError['message'],
                array('code' => $lastError['type'], 'message' => $lastError['message'], 'file' => $lastError['file'], 'line' => $lastError['line'])
            );
        }
    }

何を言ってるんだ。俺は LTSの 2.3 を使っているんだけど

そうです。LTSは 2.3 では挙動が異なります。その違いはエラー時に画面にデバッグ情報を出してくれないという点です。
Noticeエラーは画面には何もエラーがでずログには書き出されます。Fatalエラーは画面は真っ白に。これもログには書き出されます。
ログに残してくれるのはいいんですが、Fatalエラーで真っ白になるのは悲しいですね。

何を言ってるんだ。俺は monolog は使っているが Symfony を使ってないんだけど

おまけです。monologさえ使っていれば ErrorUnadler::register にロガーを登録しておけばPHPのFatalエラーもよしなにログに残してくれるようになります。(monolog >= 1.6)

<?php
require_once __DIR__.'/../vendor/autoload.php';

use Monolog\Logger;
use Monolog\Handler\StreamHandler;

$log = new Logger('name');
$log->pushHandler(new StreamHandler(__DIR__ . '/your.log', Logger::WARNING));
\Monolog\ErrorHandler::register($log); // UtilのErrorHandler::registerにロガーを登録

$a = str_repeat('1234567890', 10000000000000000); // メモリ不足エラーを意図的に発生させる

// add records to the log
$log->addWarning('Foo');
$log->addError('Bar');

するとログには

[2014-12-09 01:05:23] name.ALERT: Fatal Error (E_ERROR): Allowed memory size of 134217728 bytes exhausted (tried to allocate 100000000000000001 bytes) {"code":1,"message":"Allowed memory size of 134217728 bytes exhausted (tried to allocate 100000000000000001 bytes)","file":"/private/var/www/sf-sample/web/app.php","line":15} []

とメモリ不足のFatalエラーが記録されました。素敵ですね。
自前で同じようなことをやろうとするとほんと面倒で涙がでてくるので monolog さまさまです。

このmonolog の Utilの使い方については全くといっていいほど紹介してくれている記事がなかったので、この機会にまとめてみました。

PHPでアプリを作っている方のお役に立てれば幸いです。

明日は PHP Mentorsのitemanさんです！お楽しみに！