はじめに
エラー調査をする際にstacktraceを活用すると思います。
しかしあるとき、設定しているmax_execution_timeを超えたというエラーを調査する際に、出力された内容にstacktraceがなく調査が難航しました。
なんで出力してくれないんだよ！と思いながらもその理由を深ぼってみました。
最初に結論
FatalErrorの場合はstacktraceを渡さずにErrorのインスタンスを生成しているため、ログ出力されていなかった。
検証した環境
PHP 8.2
Laravel 10.45.1
調査開始！
1. まずはローカル環境で再現させる
準備
- php.iniで設定してある
max_execution_timeを1秒に変更 - 無限ループさせる処理を埋め込む
出力されたログ
エラー内容
FatalError
HTTP 500 Internal Server Error
Maximum execution time of 1 second exceeded
Symfony\Component\ErrorHandler\Error\FatalError {#637 ▼
-error: array:4 [▼
"type" => 1
"message" => "Maximum execution time of 1 second exceeded"
"file" => "/var/www/html/app/Http/Controllers/IndexController.php"
"line" => 46
]
}
2. FatalErrorが発生している事がわかったので、debug_print_backtrace()を使ってstacktraceを出力してみる
出力したスタックトレース
#0 /var/www/html/vendor/laravel/framework/src/Illuminate/Foundation/Bootstrap/HandleExceptions.php(244): Symfony\Component\ErrorHandler\Error\FatalError->__construct('...', 0, Array, 0)
#1 /var/www/html/vendor/laravel/framework/src/Illuminate/Foundation/Bootstrap/HandleExceptions.php(231): Illuminate\Foundation\Bootstrap\HandleExceptions->fatalErrorFromPhpError(Array, 0)
#2 /var/www/html/vendor/laravel/framework/src/Illuminate/Foundation/Bootstrap/HandleExceptions.php(255): Illuminate\Foundation\Bootstrap\HandleExceptions->handleShutdown() #3 [internal function]: Illuminate\Foundation\Bootstrap\HandleExceptions->Illuminate\Foundation\Bootstrap\{closure}()
3. stacktraceを遡ってコードを読む
エラーの発生箇所
FatalErrorインスタンスを生成して後続処理に渡している箇所を発見しました。
このインスタンスがログ出力されているようです。
HandleExceptions.phpのソースコードを読む
-
handleShutdown()メソッド内でfatalErrorFromPhpErrorは実行されているようだ
-
handleShutdown()はregister_shutdown_functionのコールバック関数として定義されている
問題のFatalErrorを発生させているのは、HandleExeptionsのbootstrap()内の処理だということがわかりました。
4. HandleExceptionsのbootstrap()はどこで呼ばれているのか
-
$bootstrappersプロパティの配列に\Illuminate\Foundation\Bootstrap\HandleExceptions::classが含まれている
-
$this->bootstrappersを引数としてbootstrapWith()が実行されている
- Kernelクラスの
bootstrap()は、handle()内にあるsendRequestThroughRouter()の中で実行されている
最後にKernelクラスを生成してhandle()の処理が行われている箇所がわかれば全体の流れが見えてきそう。
5. LaravelのKernelクラスはどこで生成されているのか
ここは扱っているシステムによってカスタマイズしてそうですが、私が扱っているシステムではbootstrap/app.phpとpublic/index.phpに処理を記載して生成処理を行っていました。
bootstrap/app.php
$app->singleton(
Illuminate\Contracts\Http\Kernel::class, // interfaceで指定している
App\Http\Kernel::class
);
return $app;
public/index.php
$app = require_once __DIR__.'/../bootstrap/app.php';
$kernel = $app->make(Kernel::class);
$response = $kernel->handle(
$request = Request::capture()
)->send();
$kernel->terminate($request, $response);
調査結果!!
-
max_execution_timeを超えた場合、E_ERROR（重大な実行時のエラーで処理が中断されます）が発生する - E_ERRORが発生した場合、FatalErrorとして処理される
- FatalErrorの場合はstacktraceを渡さずにインスタンスを生成している
- Laravelでは
E_COMPILE_ERROR、E_CORE_ERROR、E_ERROR、E_PARSEのエラーが発生した時はFatalErrorとして処理される
- Laravelでは
- FatalErrorの内容をログ出力しているのでstacktraceが出力されていなかった訳でした！
参考
PHPのエラーを理解してLaravelのエラーハンドリングをカスタマイズする
register_shutdown_function
PHPの定義済み定数
終わり
stacktraceはどんな時も欲しい！！
Discussion