💭

phpのmax_execution_timeを超えて処理された場合にstacktraceがない理由を深ぼってみた

ryusukeeee

2024/05/15に公開

Laravel

PHP

tech

はじめに

エラー調査をする際に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として処理される
FatalErrorの内容をログ出力しているのでstacktraceが出力されていなかった訳でした！

参考

PHPのエラーを理解してLaravelのエラーハンドリングをカスタマイズする
 register_shutdown_function
PHPの定義済み定数

終わり

stacktraceはどんな時も欲しい！！

レバテック開発部

レバテック開発部の公式テックブログです！レバテック開発部 Advent Calendar 2024 実施中: qiita.com/advent-calendar/2024/levtech