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

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

前言

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

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

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

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

相关地址

Package 地址:laravel-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_QUERYLOG_REQUEST 配置参数来开启关闭 sql 日志和 request 日志

思路

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

实现

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

  • RequestLog 中间件中触发 RequestArrivedEventRequestHandledEvent 事件
  • 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\LoggerWebProcessor 来增加额外的 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\LoggerWebProcessor 中检查 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"
    }
}

特别说明

其他

如果对您的日常工作有所帮助或启发,欢迎三连 star + fork + follow

如果有任何批评建议,通过邮箱(longjian.huang@foxmail.com)的方式可以联系到我。

总之,欢迎各路英雄好汉。

QQ 群:1105120693

本作品采用《CC 协议》,转载必须注明作者和本文链接
本帖由系统于 3年前 自动加精
Jianne
《L04 微信小程序从零到发布》
从小程序个人账户申请开始,带你一步步进行开发一个微信小程序,直到提交微信控制台上线发布。
《L03 构架 API 服务器》
你将学到如 RESTFul 设计风格、PostMan 的使用、OAuth 流程,JWT 概念及使用 和 API 开发相关的进阶知识。
讨论数量: 12

已经在新项目中应用 :+1:

3年前 评论
Jianne

@Miraclo :smirk:

3年前 评论

有一个问题,这种记录方式有些属于嵌入式了,会不会对api接口的性能有一定影响呢?

3年前 评论
Jianne

@MrCong laravel-logger 主要是用来帮助线上排查问题,对于同一个 api 请求能够追溯执行流程。所以,在实际使用时应该考虑:

  • 在 debug 时开启,LOG_QUERYLOG_REQUEST配置为 true
  • QUEUE_CONNECTION 设置成 redis 等队列,使用 Job 来完成日志记录
3年前 评论

支持开源👍

3年前 评论

在配置了cdn的情况下好像不能识别真实ip,导致unique_id都是一样的

2年前 评论

“贱内”这个jiannei,在古代就是自己的妻子的意思!这个容易出精品!哈哈,调侃下网名!

2年前 评论
Jianne

@dongzhiyu 其实是方言,并不是拼音

2年前 评论
dongzhiyu 2年前

Unable to JSON encode payload. Error code: 5

克隆lumen-start-api在本地,报这个错误

我单独composer日志包,同样如此

1年前 评论

太强了,学习一下

6天前 评论

讨论应以学习和精进为目的。请勿发布不友善或者负能量的内容,与人为善,比聪明更重要!