# Mololog 的 Buffer Handler

###### tags: `Laravel`,`PHP`,`Octane`,`Mololog`

這篇要記錄一下 Mololog 的 Buffer 運作，原因是從 PHP-FPM 轉換成 RoadRunner 踩到一個坑，為何原本 Log 幾乎是每個 HTTP 請求即時紀錄，轉換成 RoadRunner 後卻延遲一陣子才會出現多筆 HTTP 請求記錄？

[Mololog](https://github.com/Seldaek/monolog/tree/main) 是主流的 Log 管理套件，包含 Laravel 等 framework 都使用其套件做 Log 管理。

Mololog 的 Buffer Handler 用處是先把 log 儲存到 Buffer 中，等到達到設定數量上限(`bufferLimit`)或是調用 flush or close method 才會送出到目標文件。大部分線上環境會啟用 Buffer Handler，原因是避免頻繁的日誌寫入產生高 I/O 開銷，但會造成非即時性的 log。

<?php

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

$log = new Logger('app');

// 創建 Stream Handler
$fileHandler = new StreamHandler(__DIR__ . '/app.log', Logger::DEBUG);

// 包裝到 Buffer Handler 中
$bufferLimit = 100; // Buffer 累積 100 筆 log 再送出
$bufferHandler = new BufferHandler($fileHandler, $bufferLimit, Logger::DEBUG, true);

// 添加處理器至 Monolog
$log->pushHandler($bufferHandler);

// 添加日誌條目
$log->info('This is an informational message');
$log->debug('Debugging information');
$log->error('An error occurred');

以上程式，在緩存達到限制前，日誌不會被立即寫入到 `app.log` 文件。但可以手動執行觸發 `$bufferHandler->flush()` 或 `$bufferHandler->close()`(`close()` 包含執行 `flush()`)，不過一般來說不需自行控制 buffer flush or close，整合 Monolog 的框架會幫忙處理，查看 Laravel `public/index.php`，可以看到最後有這一段 `terminate` 執行收尾動作，例如紀錄 Log、Session 儲存等：

$kernel->terminate($request, $response);

terminate 階段在不同 PHP Runtime 又有不同行為：
- PHP-FPM：
在 PHP-FPM 架構下，worker 在每次 HTTP 請求結束後會釋放所有該請求過程中分配的記憶體，並清除變數、物件、資源（例如檔案、DB 連線等），也就是說每次請求會完整執行 Laravel `public/index.php` 內容，從建立 app & kernel，處理 [Request Lifecycle](https://laravel.com/docs/master/lifecycle)，到發送 response，以及最後的 kernel terminate，下一個 HTTP 請求再重新前述流程。所以不論 `bufferLimit` 上限設定多高，每次請求最終在 kernel terminate 階段都會把 log 送出。
- Laravel Octane：
在 Octane 架構下，只有在 octane start 時會建立 app & kernel，之後每個 HTTP 請求，並不會走 `public/index.php` 流程，而是持續使用一開始建立的 app & kernel，請求結束後不會釋放所有該請求過程中分配的記憶體，也沒有清除變數、物件、資源和 kernel terminate 階段。所以導致 log 會累積到數量上限(`bufferLimit`)後才會送出。
為了解決 Octane 架構這問題，有兩種解法：
- 調低數量上限(`bufferLimit`)
原本上面範例的 `bufferLimit` 是 100，調低成 10 筆就送出，而開發或測試環境可能有即時紀錄 log 需求，可設定成 1 筆就送出，或是不使用 BufferHandler，所以需要把 `bufferLimit` 變成環境變數處理。
- 維持每個 reqeust 結束後執行 Mololog flush
`config/octane.php` 的 `listeners` 有個屬性是 `RequestTerminated`，這邊就是設定每個 HTTP 請求結束後要執行哪些 Handlers，陣列加上 `CloseMonologHandlers::class`，每次 reqeust 結束時就會進行 Monolog flush(Monolog close 包含執行 flush)

        RequestTerminated::class => [
            CloseMonologHandlers::class,
        ],

另外有使用 session、storage、queue、middleware 等需要 kernel terminate 階段才會送出或上傳的功能，也需要注意是否有類似問題，Octane 有一系列 [flush 的 handlers](https://github.com/laravel/octane/tree/2.x/src/Listeners)，例如 `FlushSessionState`、`FlushDatabaseQueryLog`、`FlushUploadedFiles` 等等，可視情況使用。