日志增加request_id

日志增加request_id，可以通过关键字查看整个日志的链路信息，提升bug查找速度，以及外部对接进度。

hyperf和传统的框架不同，传统框架可以通过request，在框架初始化时增加request_id，实现整个进程日志记录同一个request_id，但是hyperf是协程的方式运作的，当我们使用协程时，request_id会因为协程的使用而导致request_id记录有误，链路无法实现对齐。通过长时间的摸索，总结出一套完善的记录日志机制，用于hyperf1.1记录日志增加request_id。

目前整体的思路是通过协程上下文增加request_id。

过程

初始化logger组件时，monolog增加初始化的request_id

<?php

declare(strict_types=1);
/**
 * This file is part of Hyperf.
 *
 * @link     https://www.hyperf.io
 * @document https://hyperf.wiki
 * @contact  group@hyperf.io
 * @license  https://github.com/hyperf/hyperf/blob/master/LICENSE
 */
namespace App\Kernel\Log;

use Hyperf\Di\Annotation\Inject;
use App\Service\UtilService;
use Monolog\Processor\ProcessorInterface;

class AppendExtraProcessor implements ProcessorInterface
{
    /**
     * @Inject()
     *
     * @var UtilService
     */
    public $utilService;

    public function __invoke(array $records)
    {
        $records['extra']['request_id'] = $this->utilService->getRequestId();
        return $records;
    }
}

至于说getRequestId()的日志方式，实际上是逐级循环，获取最顶级的Continue::id对应的request_id，如果没有，当前协程中set一个request_id，子协程获取当前协程的request_id，实现协程中的request_id统一。

public function getRequestId()
{
    $coroutineId = Coroutine::id();
    $requestId = '';

    while ($coroutineId > 0) {

        $loopRequestId = Context::get('requestId', '', $coroutineId);
        if ($loopRequestId) {
            $requestId = $loopRequestId;
            break;
        }

        $pid = Coroutine::getPcid($coroutineId);

        if (! empty($pid)) {
            $loopRequestPid = '';
            if (Context::has('requestId', $pid ?? 0)) {
                $loopRequestPid = Context::get('requestId', '', $pid);
            }

            if ($loopRequestPid) {
                Context::copy($pid, ['requestId']);
                $requestId = $loopRequestPid;
                break;
            }
        }

        if ($pid == -1 || $pid == '' || $pid == $coroutineId) {
            $genRequestId = session_create_id();
            Context::set('requestId', $genRequestId);
            $requestId = $genRequestId;
            break;
        }

        $coroutineId = $pid;
    }

    return $requestId;
}

建立中间件，记录请求Log，并将request_id set 到协程上下文中

此时的协程处于初始化状态，也就是顶级，此处也可以在nginx中set一个 X-REQUEST-ID

<?php

namespace App\Middleware;


use Hyperf\Di\Annotation\Inject;
use Hyperf\Utils\Context;
use Hyperf\Logger\LoggerFactory;
use Psr\Container\ContainerInterface;
use Psr\Http\Message\ResponseInterface;
use Psr\Http\Message\ServerRequestInterface;
use Psr\Http\Server\MiddlewareInterface;
use Psr\Http\Server\RequestHandlerInterface;
use Hyperf\HttpServer\Contract\ResponseInterface as HttpResponse;

//记录请求日志中间件
class RequestLogMiddleware implements MiddlewareInterface
{

    /**
     * @Inject
     * @var LoggerFactory
     */
    public $requestLog;

    protected $response;

    /**
     * @var ContainerInterface
     */
    protected $container;


    public function __construct(HttpResponse $response)
    {
        $this->response = $response;
    }


    public function process(ServerRequestInterface $request, RequestHandlerInterface $handler): ResponseInterface
    {

        try{
            $time = date('Y-m-d H:i:s');

            $headers = $request->getHeaders();
            $requestId = isset($headers['x-request-id']) ? $headers['x-request-id'][0] : session_create_id();
            Context::set('requestId', $requestId);
            
            // todo 覆盖request_id，重写Context
            $request = Context::override(ServerRequestInterface::class, function (ServerRequestInterface $request) use(&$requestId) {
                $request = $request->withAddedHeader('request_id', $requestId);
                return $request;
            });

            $this->requestLog->get('log', 'request')->info("接口请求日志--$time", [
                'postParam' => $request->getParsedBody(),
                'getParam' => $request->getQueryParams(),
                'uri' => $request->getServerParams(),
                'headers' => $headers,
                'file' => $request->getUploadedFiles()
            ]);

            return $handler->handle($request);

        }catch(\Exception $e){

            return $this->response->json(['code' => 500,'message' => '请求初始化失败--'.$e->getMessage(),'data'=>[]]);
        }

    }
}

此时记录一个请求接入的log就已经存在了request_id，这时候更改logger.log的config配置层，将AppendExtraProcessor加载至logger

'request' => [
    'handler' => [
        'class' => Monolog\Handler\RotatingFileHandler::class,
        'constructor' => [
            'filename' => BASE_PATH . '/runtime/logs/api_request.log',
            'level' => Monolog\Logger::INFO,
        ],
    ],
    'formatter' => [
        'class' => Monolog\Formatter\JsonFormatter::class,
        'constructor' => [
            'format' => null,
            'dateFormat' => null,
            'allowInlineLineBreaks' => true,
        ],
    ],
    'processors' => [
        [
            'class' => \App\Kernel\Log\AppendExtraProcessor::class,
        ],
    ],
],

此时，每一个记录至monolog的日志，都会有request_id。

目前hyperf1.1中，如果直接使用co(function(){})的话，是无法获取有效的request_id，所以需要在外部协程环境下，先get出request_id，然后将request_id作为参数set进子协程中。

$requestId = Context::get('request_id');
co(function () use ($requestId) {
    Context::set('request_id', $requestId);
    $this->requestLog->get('log', 'request')->info('xxxx');
});

这样就可以保证request_id一致。

sql日志记录request_id

因为sql是使用事件触发的形式，本人亲测无法获取正确的request_id，所以在RequestLogMiddler中，有这么一段代码：


$request = Context::override(ServerRequestInterface::class, function (ServerRequestInterface $request) use(&$requestId) {
    $request = $request->withAddedHeader('request_id', $requestId);
    return $request;
});

这一步是将request_id记录至request的header中，进入dbQueryListener页面。

<?php

declare(strict_types=1);
/**
 * This file is part of Hyperf.
 *
 * @link     https://www.hyperf.io
 * @document https://doc.hyperf.io
 * @contact  group@hyperf.io
 * @license  https://github.com/hyperf-cloud/hyperf/blob/master/LICENSE
 */

namespace App\Listener;

use Hyperf\Database\Events\QueryExecuted;
use Hyperf\Event\Annotation\Listener;
use Hyperf\Event\Contract\ListenerInterface;
use Hyperf\Logger\LoggerFactory;
use Hyperf\Utils\Arr;
use Hyperf\Utils\Context;
use Hyperf\Utils\Str;
use Psr\Container\ContainerInterface;
use Psr\Http\Message\ServerRequestInterface;
use Psr\Http\Server\RequestHandlerInterface;
use Psr\Log\LoggerInterface;

/**
 * @Listener
 */
class DbQueryExecutedListener implements ListenerInterface
{
    /**
     * @var LoggerInterface
     */
    private $logger;

    public function __construct(ContainerInterface $container)
    {
        $this->logger = $container->get(LoggerFactory::class)->get('log', 'request');
    }

    public function listen(): array
    {
        return [
            QueryExecuted::class,
        ];
    }

    /**
     * @param QueryExecuted $event
     */
    public function process(object $event)
    {
        if ($event instanceof QueryExecuted) {
            $sql = $event->sql;
            if (! Arr::isAssoc($event->bindings)) {
                foreach ($event->bindings as $key => $value) {
                    $sql = Str::replaceFirst('?', "'{$value}'", $sql);
                }
            }

            $headers= Context::get(ServerRequestInterface::class)->getHeaders();

            if (isset($headers['request_id']) && isset($headers['request_id'][0])) {
                Context::set('request_id', $headers['request_id'][0]);
                $this->logger->info($sql);
            }
        }
    }
}

从header中取出request_id，然后set进context中，可以保证sql对应的request_id和普通日志的request_id一致。

总结

马马虎虎，可以实现功能，日志就此结束，基本功能已经实现，出现的坑也已经基本踏平。可以研究日志告警机制。

日志增加request_id

过程

初始化logger组件时，monolog增加初始化的request_id

建立中间件，记录请求Log，并将request_id set 到 协程上下文中

sql日志记录request_id

总结

建立中间件，记录请求Log，并将request_id set 到协程上下文中