Monolog 優化及打造 ELK 友好的日誌格式

leo發表於2017-01-04
Mono優化

Monolog 是目前最流行的php日誌庫，許多流行的php框架都用Monolog作為預設的日誌庫，例如symfony、laravel。

預設情況下，symfony、laravel在列印日誌時都是來一條日誌就列印一行到日誌檔案，這樣就沒有辦法按照請求將日誌聚合起來，更麻煩的是，多個併發的請求列印的日誌是交叉的，這給本地除錯、線上排查bug帶來了許多麻煩。

我希望的結果是：

  • 一次請求所產生的日誌是緊密相連的，不會因為高併發而產生日誌交叉的情況。
  • 能夠通過Logstash的multiline來聚合一次請求所產生的所有日誌。
  • 一些訪問資料（如訪問時間、訪問者IP、訪問的Url、該請求的執行時間等）能夠被Logstash直接解析成欄位，並能夠在Kibana中查詢、篩選。

最終程式碼如下：

namespace App\Extensions\Log;

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

class AggregateFileHandler extends StreamHandler
{
    public function handleBatch(array $records)
    {
        $dur     = number_format(microtime(true) - LARAVEL_START, 3);
        $request = request();
        $format  = 'Y-m-d H:i:s.u';
        // 這一行是我們這個處理器自己加上的日誌，記錄請求時間、響應時間、訪客IP，請求方法、請求Url
        $log     = sprintf(
            "[%s][%s]%s %s %s\n",
            Carbon::createFromFormat('U.u', sprintf('%.6F', LARAVEL_START), config('app.timezone'))->format($format),
            $dur,
            $request->getClientIp(),
            $request->getMethod(),
            $request->getRequestUri()
        );
        // 然後將記憶體中的日誌追加到$log這個變數裡
        foreach ($records as $record) {
            if (!$this->isHandling($record)) {
                continue;
            }
            $record = $this->processRecord($record);
            $log .= $this->getFormatter()->format($record);
        }
        // 呼叫日誌寫入方法
        $this->write(['formatted' => $log]);
    }
}

需要BufferHandler來配合使用：

$handler = new AggregateFileHandler($path_to_log_file);
$handler->setFormatter(
    new LineFormatter("[%datetime%]%level_name% %message% %context% %extra%\n", 'i:s', true, true)
);
$monolog->pushHandler(new BufferHandler($handler));

AggregateRotatingFileHandler類只實現了一個handleBatch方法，BufferHandler會在請求結束時去呼叫handleBatch方法，因為我們不考慮單獨使用這個處理器的情況，所以就沒有去重寫handler方法（實際上重寫了也沒法滿足我們的需求）。

Logstash的配置如下：

input {
    file {
        type => 'monolog'
        path => "/home/vagrant/website/logs/app.log"
    }
}
filter {
    if [type] == 'monolog' {
        multiline {
            pattern => "\[[\d\-\: ]+?\]\[[\d\.]+?\]\d+\.\d+\.\d+\.\d+ \S+ \S+"
            negate => true
            what => "previous"
        }
        grok {
            match => ["message", "\[%{TIMESTAMP_ISO8601:time}\]\[%{NUMBER:duration}\]%{IP:ip} %{WORD:method} %{DATA:url}\n%{GREEDYDATA:data}"]
        }
    }
}

貼一個從ElasticSearch中查出的日誌

{
  "_index" : "monolog",
  "_type" : "monolog",
  "_id" : "AVkgdHh4eDK8-gwc8OTf",
  "_score" : 1.0,
  "_source" : {
    "message" : "[2016-12-21 08:16:27.373000][2.421]127.0.0.1 GET / \n[16:29]INFO Test Log 1\n[16:29]INFO Test Log 2",
    "@version" : "1",
    "@timestamp" : "2016-12-21T08:16:55.485Z",
    "path" : "/home/vagrant/online/website/logs/monolog.log",
    "host" : "0.0.0.0",
    "type" : "monolog",
    "tags" : [ "multiline" ],
    "time" : "2016-12-21 08:16:27.373000",
    "duration" : "2.421",
    "ip" : "127.0.0.1",
    "method" : "GET",
    "url" : "/",
    "data" : "[16:29]INFO Test Log 1\n[16:29]INFO Test Log 2"
  }
}
本作品採用《CC 協議》，轉載必須註明作者和本文連結

相關文章