教你更优雅地写 API 之「记录日志」

Jianne 的个人博客 / 75 / 13 / 创建于 4年前 / 更新于 4年前

教你更优雅地写 API 之「记录日志」

前言

日常工作中，项目不管是在开发阶段，还是已经部署上线，记录日志来分析项目的运行情况都是很常用的方式。比如，通过记录 SQL 日志来检查是否有 N+1 问题，通过记录请求日志来分析 API 的响应时间等。

在 lumen-api-starter 中针对记录日志进行了优化，可以更方便地来记录 SQL 和 Request日志。

关于lumen-api-starter 的介绍可以参考文章是时候使用 Lumen 8 + API Resource 开发项目了！。

本篇是在前一篇的基础上，重新整理并独立出了 package，可以同时支持最新版本 Laravel 和 Lumen 项目。

相关地址：

Package 地址：l aravel-logger

Laravel 版本 Api 开发初始化项目：laravel-api-starter

Lumen 版本 Api 开发初始化项目：lumen-api-starter

实现过程

需求

能够有效地记录 SQL 日志，来分析隐藏的 N+1 、慢查询等问题
能够记录 API 请求日志，来分析响应时间；
可以追溯单次请求中的执行过程（并发场景下传统文件日志方式可能会出现串行）
日志能够更容易地查看和搜索
能够反向追溯应用中所有记录日志的节点
日志记录不会额外对业务处理增加负担
能够灵活地配置开启和关闭

功能

提供 logger_async 辅助函数，通过异步 Job 方式来记录日志；
增加 RequestLog 中间件来记录 api 的请求和响应；对于单个请求关联 UNIQUE_ID，根据UNIQUE_ID可以跟踪请求执行过程
适配 MongoDB 驱动，支持记录日志到 MongoDB；collection 支持按天、按月和按年拆分；
日志的 message 适配 laravel-enum，统一日志的 message 格式；方便统计项目中记录日志的节点
提供 LOG_QUERY、LOG_REQUEST 配置参数来开启关闭 sql 日志和 request 日志

思路

通过 DB::listen 来监听 SQL 的执行并生成 SQL 日志记录
通过 RequestLog 中间件中的 handle 方法来生成请求 UNIQUE_ID ，terminate 方法来记录 Request 日志
在单次请求过程中，所有的日志记录都关联 RequestLog 中间件中产生的UNIQUE_ID
日志支持异步方式记录，来减少业务负担；（LogJob 走 default 队列，生产环境可以将优先级高的异步任务放在其他队列中）
logger_async 辅助函数，用来便捷调度 LogJob

实现

针对 larave-logger源码分析下大致流程。

RequestLog 中间件中触发 RequestArrivedEvent 和 RequestHandledEvent 事件
RequestArrivedListener 监听 RequestArrivedEvent 事件，往 server 中写入 UNIQUE_ID
RequestHandledListener 监听 RequestHandledEvent 事件，通过 logger_async 调度 LogJob
logger_async 辅助函数中调度 LogJob 时末尾参数传入 request()->server()

function logger_async(string $message, array $context = [])
{
    return dispatch(new \Jiannei\Logger\Laravel\Jobs\LogJob($message, $context, request()->server()));
}

LogJob 中通过Monolog\Logger 的 WebProcessor 来增加额外的 SERVER 信息（url、ip、http_method 等）到日志中

// vendor/jiannei/laravel-logger/src/Jobs/LogJob.php

<?php
namespace Jiannei\Logger\Laravel\Jobs;

use Illuminate\Bus\Queueable;
use Illuminate\Contracts\Queue\ShouldQueue;
use Illuminate\Queue\InteractsWithQueue;
use Monolog\Logger;
use Monolog\Processor\WebProcessor;
use Psr\Log\LoggerInterface;

class LogJob implements ShouldQueue
{
    use InteractsWithQueue;
    use Queueable;

    private $context;
    private $message;
    private $serverData;

    public function __construct(string $message, array $context = null, array $serverData = null)
    {
        $this->message = $message;
        $this->context = $context;
        $this->serverData = $serverData;
    }

    public function handle()
    {
        app()->forgetInstance(LoggerInterface::class);
        // unset(app()[LoggerInterface::class]);

        $logger = app(LoggerInterface::class)->getLogger();
        if ($logger instanceof Logger) {
            $logger->pushProcessor(new WebProcessor($this->serverData));
        }

        $logger->debug($this->message, $this->context);
    }
}

Monolog\Logger 的 WebProcessor 中检查 serverData 中是否有UNIQUE_ID，如果有则记录到日志的 extra 字段中

// vendor/monolog/monolog/src/Monolog/Processor/WebProcessor.php
<?php

// ...

class WebProcessor implements ProcessorInterface
{
    /**
     * @var array|\ArrayAccess
     */
    protected $serverData;

    /**
     * Default fields
     *
     * Array is structured as [key in record.extra => key in $serverData]
     *
     * @var array
     */
    protected $extraFields = [
        'url'         => 'REQUEST_URI',
        'ip'          => 'REMOTE_ADDR',
        'http_method' => 'REQUEST_METHOD',
        'server'      => 'SERVER_NAME',
        'referrer'    => 'HTTP_REFERER',
    ];

    public function __construct($serverData = null, array $extraFields = null)
    {
        if (null === $serverData) {
            $this->serverData = &$_SERVER;
        } elseif (is_array($serverData) || $serverData instanceof \ArrayAccess) {
            $this->serverData = $serverData;
        } else {
            throw new \UnexpectedValueException('$serverData must be an array or object implementing ArrayAccess.');
        }

        if (isset($this->serverData['UNIQUE_ID'])) {
            $this->extraFields['unique_id'] = 'UNIQUE_ID';
        }

        if (null !== $extraFields) {
            if (isset($extraFields[0])) {
                foreach (array_keys($this->extraFields) as $fieldName) {
                    if (!in_array($fieldName, $extraFields)) {
                        unset($this->extraFields[$fieldName]);
                    }
                }
            } else {
                $this->extraFields = $extraFields;
            }
        }
    }

如何使用

安装

composer require jiannei/laravel-enum -vvv
composer require jiannei/laravel-logger -vvv

配置

注册服务容器（Laravel 可以省略这一步骤）

Lumen在 bootstrap/app.php 中注册服务容器

$app->register(\Jiannei\Logger\Laravel\Providers\ServiceProvider::class);

中间件启用

Laravel 在 app/Http/Kernel.php 的 $middlewareGroups 中添加

protected $middlewareGroups = [
    'api' => [
        \Jiannei\Logger\Laravel\Http\Middleware\RequestLog::class,// 加在这个地方
    ],
];

Lumen 在 bootstrap/app.php 中添加

$app->middleware([
    \Jiannei\Logger\Laravel\Http\Middleware\RequestLog::class,
]);

修改配置参数

config/logging.php 中增加以下配置，并根据自身实际情况进行部分调整，可以对比查看最终配置 lumen-api-starter

'channels' => [// 下面这些移到原先的 channels 中
    'mongo' => [
        'driver' => 'custom', // 此处必须为 custom
        'via' => \Jiannei\Logger\Laravel\MongoLogger::class, // 当 driver 设置为 custom 时，使用 via 配置项所指向的工厂类创建 logger

        'channel' => env('LOG_MONGODB_CHANNEL', 'mongo'),
        'level' => env('LOG_MONGODB_LEVEL', 'debug'), // 日志级别
        'separate' => env('LOG_MONGODB_SEPARATE', false), // false,daily,monthly,yearly

        'host' => env('LOG_MONGODB_HOST', config('database.connections.mongodb.host')),
        'port' => env('LOG_MONGODB_PORT', config('database.connections.mongodb.port')),
        'username' => env('LOG_MONGODB_USERNAME', config('database.connections.mongodb.username')),
        'password' => env('LOG_MONGODB_PASSWORD', config('database.connections.mongodb.password')),
        'database' => env('LOG_MONGODB_DATABASE', config('database.connections.mongodb.database')),
    ],
],

// 下面是新增项，移到文件末尾即可

'enum' => \Jiannei\Enum\Laravel\Repositories\Enums\LogEnum::class,

'query' => [
    'enabled' => env('LOG_QUERY', false),

    // Only record queries that are slower than the following time
    // Unit: milliseconds
    'slower_than' => 0,
],

'request' => [
    'enabled' => env('LOG_REQUEST', false),
],

.env 中配置

LOG_CHANNEL=mongo
LOG_SLACK_WEBHOOK_URL=
LOG_QUERY=true
LOG_REQUEST=true
LOG_MONGODB_SEPARATE=daily
LOG_MONGODB_LEVEL=debug

# 如果使用的是 mongo channel 需要配置
LOG_MONGODB_SEPARATE=daily
LOG_MONGODB_LEVEL=debug
LOG_MONGODB_HOST=127.0.0.1
LOG_MONGODB_PORT=27017
LOG_MONGODB_DATABASE=logs
LOG_MONGODB_USERNAME=
LOG_MONGODB_PASSWORD=
LOG_MONGODB_AUTHENTICATION_DATABASE=admin

如果需要记录日志到 MongoDB，需要先安装并配置laravel-mongodb

如何使用

可以参考 lumen-api-starter 中的实际使用示例。

使用

app/Repositories/Enums/LogEnum.php 中定义记录日志时的 message
通过 logger_async 方法记录日志

logger_async(LogEnum::SYSTEM_SQL, $arrayData);

如果队列任务异步执行，则需要开启队列消费 php artisan queue:work

教你更优雅地写 API 之「记录日志」

日志内容

记录到文件中的日志内容

[2021-01-18 12:03:36] local.DEBUG: System sql {"database":"lumen-api","duration":"11.08ms","sql":"select `roles`.*, `model_has_roles`.`model_id` as `pivot_model_id`, `model_has_roles`.`role_id` as `pivot_role_id`, `model_has_roles`.`model_type` as `pivot_model_type` from `roles` inner join `model_has_roles` on `roles`.`id` = `model_has_roles`.`role_id` where `model_has_roles`.`model_id` = '11' and `model_has_roles`.`model_type` = 'App\\\\Repositories\\\\Models\\\\User'"} {"url":"/users","ip":"172.22.0.1","http_method":"get","server":"lumen-api.test","referrer":null,"unique_id":"43f54ea9-4ad4-47cf-b9da-1d3aa150ff61"}
[2021-01-18 12:03:36] local.DEBUG: System request {"request":[],"response":{"status":"success","code":200,"message":"操作成功","data":{"data":[{"id":1,"nickname":"Evert Stracke DVM","email":"aufderhar.kaden@example.net"},{"id":2,"nickname":"Milton Toy","email":"keagan.eichmann@example.org"},{"id":3,"nickname":"Mrs. Alyce O'Hara","email":"cartwright.sidney@example.org"},{"id":4,"nickname":"Prof. Evalyn Windler I","email":"bertram.bartoletti@example.org"},{"id":5,"nickname":"Brant Skiles","email":"jane16@example.net"},{"id":6,"nickname":"Sage Rodriguez I","email":"ryder50@example.org"},{"id":7,"nickname":"Ms. Angelica Wiegand DVM","email":"kaelyn.mueller@example.net"},{"id":8,"nickname":"Newton Zieme","email":"sipes.kip@example.com"},{"id":9,"nickname":"Natalia Ruecker","email":"stroman.kiley@example.com"},{"id":10,"nickname":"Hallie Parisian","email":"rosina74@example.net"},{"id":11,"nickname":"Jiannei","email":"longjian.huang@foxmail.com"}],"meta":{"pagination":{"total":11,"count":11,"per_page":15,"current_page":1,"total_pages":1,"links":[]}}},"error":[]},"start":1610942614.450748,"end":1610942615.785696,"duration":"1.33s"} {"url":"/users","ip":"172.22.0.1","http_method":"GET","server":"lumen-api.test","referrer":null,"unique_id":"43f54ea9-4ad4-47cf-b9da-1d3aa150ff61"}

记录到 Mongodb 的日志内容

/* 1 */
{
    "_id" : ObjectId("60050999ee7d025d4c62c8c2"),
    "message" : "System sql",
    "context" : {
        "database" : "lumen-api",
        "duration" : "54.19ms",
        "sql" : "select count(*) as aggregate from `users`"
    },
    "level" : 100,
    "level_name" : "DEBUG",
    "channel" : "mongo",
    "datetime" : ISODate("2021-01-18T12:07:53.410+08:00"),
    "extra" : {
        "url" : "/users",
        "ip" : "172.22.0.1",
        "http_method" : "get",
        "server" : "lumen-api.test",
        "referrer" : null,
        "unique_id" : "0cda1927-bf14-4acf-88e8-1d9ed67170b5"
    }
}

/* 2 */
{
    "_id" : ObjectId("60050999ee7d025d4c62c8c3"),
    "message" : "System sql",
    "context" : {
        "database" : "lumen-api",
        "duration" : "2.42ms",
        "sql" : "select * from `users` limit 15 offset 0"
    },
    "level" : 100,
    "level_name" : "DEBUG",
    "channel" : "mongo",
    "datetime" : ISODate("2021-01-18T12:07:53.500+08:00"),
    "extra" : {
        "url" : "/users",
        "ip" : "172.22.0.1",
        "http_method" : "get",
        "server" : "lumen-api.test",
        "referrer" : null,
        "unique_id" : "0cda1927-bf14-4acf-88e8-1d9ed67170b5"
    }
}