【日志革新】在ThinkPHP5中实现高效TraceId集成，打造可靠的日志追踪系统

问题背景

最近接手了一个骨灰级的项目，然而在项目中遇到了一个普遍的挑战：由于公司采用 ELK（Elasticsearch、Logstash、Kibana）作为日志收集和分析工具，追踪生产问题成为了一大难题。尽管 ELK 提供了强大的日志分析功能，但由于项目历史悠久，日志输出不规范，缺乏唯一标识，导致在海量日志中准确定位问题变得异常困难。为了提升生产环境下的问题排查和故障诊断效率，迫切需要在项目中引入一种机制，能够为每个请求生成唯一的标识符（traceId），并将其与 ELK 集成，以便在日志中准确追踪请求的全链路过程。

系统默认日志格式
在这里插入图片描述

elk 对这种格式采集并不太友好，所以打算重新写一个日志log类。

查看application/config.php配置文件，第一反应就是这个File到底在哪？OK，我们直接全局搜索 File.php，最终锁定文件路径：source/thinkphp/library/think/log/driver/File.php

在这里插入图片描述
基于自身业务改造，时间比较短哈，改写了一个初版（简单粗暴就是日志单行展示），可以短时间适配业务，改造后的代码如下：

<?php

namespace app\common\library;

use think\App;
use think\Request;

class YeeLog
{
    protected $config = [
        'time_format' => ' c ',
        'single'      => false,
        'file_size'   => 2097152,
        'path'        => LOG_PATH,
        'apart_level' => [],
        'max_files'   => 0,
        'json'        => true,
        'trace_id'  => null,
        'log_format'  => 'json'
    ];

    // 实例化并传入参数
    public function __construct($config = [])
    {
        if (is_array($config)) {
            $this->config = array_merge($this->config, $config);
        }
        $this->config['trace_id'] = $_SERVER['traceId'] ?? "";
    }

    /**
     * 日志写入接口
     * @access public
     * @param array $log 日志信息
     * @param bool $append 是否追加请求信息
     * @return bool
     */
    public function save(array $log = [], $append = false)
    {
        $destination = $this->getMasterLogFile();

        $path = dirname($destination);
        !is_dir($path) && mkdir($path, 0755, true);

        $info = [];
        foreach ($log as $type => $val) {

            foreach ($val as $msg) {
                if (!is_string($msg)) {
                    if ($this->config['log_format'] == 'json') {
                        $msg = json_encode($msg, 320);
                    } else {
                        $msg = var_export($msg, true);
                    }
                }

                $info[$type][] = $this->config['json'] ? $msg : $this->getCurrentTime() . ' [ ' . $type . ' ] ' . $msg;
            }

            if (!$this->config['json'] && (true === $this->config['apart_level'] || in_array($type, $this->config['apart_level']))) {
                // 独立记录的日志级别
                $filename = $this->getApartLevelFile($path, $type);

                $this->write($info[$type], $filename, true, $append);
                unset($info[$type]);
            }
        }

        if ($info) {
            return $this->write($info, $destination, false, $append);
        }

        return true;
    }

    /**
     * 获取主日志文件名
     * @access public
     * @return string
     */
    protected function getMasterLogFile()
    {
        if ($this->config['single']) {
            $name = is_string($this->config['single']) ? $this->config['single'] : 'single';

            $destination = $this->config['path'] . $name . '.log';
        } else {
            $cli = PHP_SAPI == 'cli' ? '_cli' : '';

            if ($this->config['max_files']) {
                $filename = date('Ymd') . $cli . '.log';
                $files    = glob($this->config['path'] . '*.log');

                try {
                    if (count($files) > $this->config['max_files']) {
                        unlink($files[0]);
                    }
                } catch (\Exception $e) {
                }
            } else {
                $filename = date('Ym') . DIRECTORY_SEPARATOR . date('d') . $cli . '.log';
            }

            $destination = $this->config['path'] . $filename;
        }

        return $destination;
    }

    /**
     * 获取独立日志文件名
     * @access public
     * @param string $path 日志目录
     * @param string $type 日志类型
     * @return string
     */
    protected function getApartLevelFile($path, $type)
    {
        $cli = PHP_SAPI == 'cli' ? '_cli' : '';

        if ($this->config['single']) {
            $name = is_string($this->config['single']) ? $this->config['single'] : 'single';

            $name .= '_' . $type;
        } elseif ($this->config['max_files']) {
            $name = date('Ymd') . '_' . $type . $cli;
        } else {
            $name = date('d') . '_' . $type . $cli;
        }

        return $path . DIRECTORY_SEPARATOR . $name . '.log';
    }

    /**
     * 获取当前时间戳
     * @return false|string
     */
    protected function getCurrentTime()
    {
        $customTimestamp = trim(config('log.timestamp'));
        return empty($customTimestamp) ? date($this->config['time_format']) : date($customTimestamp);
    }

    /**
     * 日志写入
     * @access protected
     * @param array $message 日志信息
     * @param string $destination 日志文件
     * @param bool $apart 是否独立文件写入
     * @param bool $append 是否追加请求信息
     * @return bool
     */
    protected function write($message, $destination, $apart = false, $append = false)
    {
        // 检测日志文件大小，超过配置大小则备份日志文件重新生成
        $this->checkLogSize($destination);

        // 日志信息封装
        $info['time'] = $this->getCurrentTime();

        foreach ($message as $type => $msg) {
            $info[$type] = is_array($msg) ? implode("\r\n", $msg) : $msg;
        }

        if (PHP_SAPI == 'cli') {
            $message = $this->parseCliLog($info);
        } else {
            // 添加调试日志
            $this->getDebugLog($info, $append, $apart);

            $message = $this->parseLog($info);
        }

        return error_log($message, 3, $destination);
    }

    /**
     * 检查日志文件大小并自动生成备份文件
     * @access protected
     * @param string $destination 日志文件
     * @return void
     */
    protected function checkLogSize($destination)
    {
        if (is_file($destination) && floor($this->config['file_size']) <= filesize($destination)) {
            try {
                rename($destination, dirname($destination) . DIRECTORY_SEPARATOR . time() . '-' . basename($destination));
            } catch (\Exception $e) {
            }
        }
    }

    /**
     * CLI日志解析
     * @access protected
     * @param array $info 日志信息
     * @return string
     */
    protected function parseCliLog($info)
    {
        if ($this->config['json']) {
            $message = json_encode($info, JSON_UNESCAPED_UNICODE | JSON_UNESCAPED_SLASHES) . "\r\n";
        } else {
            $now = $info['time'];
            unset($info['time']);

            $message = implode("\r\n", $info);

            $message = "[{$now}]" . $message . "\r\n";
        }

        return $message;
    }

    /**
     * 解析日志
     * @access protected
     * @param array $info 日志信息
     * @return string
     */
    protected function parseLog($info)
    {
        $request     = Request::instance();
        $requestInfo = [
            '[trace_id]'      => $this->config['trace_id'],
            '[request_ip]'      => getIp(),
            '[method]'          => $request->method(),
            '[domain]'          => $request->domain(),
            '[uri]'             => $request->url(),
            '[param]'           => json_encode($request->post(), 320),
            '[x-forwarded-for]' => $_SERVER['HTTP_X_FORWARDED_FOR'] ?? '--',
            '[http_x_real_ip]'  => $_SERVER['HTTP_X_REAL_IP'] ?? '--',
            '[remote_addr]'     => $_SERVER['REMOTE_ADDR'] ?? '--'
        ];

        if ($this->config['json']) {
            $info    = $requestInfo + $info;
            $println = "---------------------------------------------------------------\r\n";
            $msg     = sprintf("%s%s ", $println, $this->getCurrentTime());
            foreach ($info as $key => $value) {
                $msg .= sprintf("%s: %s ", $key, $value);
            }
            return $msg . "\r\n";
        }

        array_unshift($info, "---------------------------------------------------------------\r\n{$info['time']} [ hit ] {$this->config['trace_id']} {$requestInfo['ip']} {$requestInfo['method']} {$requestInfo['host']}{$requestInfo['uri']}");
        unset($info['time']);

        return implode("\r\n", $info) . "\r\n";
    }

    protected function getDebugLog(&$info, $append, $apart)
    {
        if (App::$debug && $append) {

            if ($this->config['json']) {
                // 获取基本信息
                $runtime = round(microtime(true) - THINK_START_TIME, 10);
                $reqs    = $runtime > 0 ? number_format(1 / $runtime, 2) : '∞';

                $memory_use = number_format((memory_get_usage() - THINK_START_MEM) / 1024, 2);

                $info = [
                        'runtime' => number_format($runtime, 6) . 's',
                        'reqs'    => $reqs . 'req/s',
                        'memory'  => $memory_use . 'kb',
                        'file'    => count(get_included_files()),
                    ] + $info;

            } elseif (!$apart) {
                // 增加额外的调试信息
                $runtime = round(microtime(true) - THINK_START_TIME, 10);
                $reqs    = $runtime > 0 ? number_format(1 / $runtime, 2) : '∞';

                $memory_use = number_format((memory_get_usage() - THINK_START_MEM) / 1024, 2);

                $time_str   = '[运行时间：' . number_format($runtime, 6) . 's] [吞吐率：' . $reqs . 'req/s]';
                $memory_str = ' [内存消耗：' . $memory_use . 'kb]';
                $file_load  = ' [文件加载：' . count(get_included_files()) . ']';

                array_unshift($info, $time_str . $memory_str . $file_load);
            }
        }
    }
}

探索日志追踪解决方案

1. 生成 traceId： 需要一个能够生成唯一 traceId 的方法，确保每个请求都有一个唯一的标识符。
2. 存储 traceId： 将生成的 traceId 存储在 $_SERVER 中，以便在整个请求处理过程中都能够方便地访问到它。
3. 添加到响应头中： 在每次请求的响应中都添加 traceId 到响应头中，以便客户端收到响应后可以通过 traceId 与请求对应起来。
4. 处理异步请求： 对于异步请求，需要在发送请求时将 traceId 包含在请求头中，以便日志也能够与对应的原始请求进行关联。

解决方案

1. 生成 traceId： 在 Tags.php 中的 app_begin 钩子中，执行以下操作：

<?php
return [
	// 应用开始
    'app_begin' => [
        'app\\api\\behavior\\TraceId'
    ],
];

2. 存储 traceId： 将生成的 traceId 存储在 $_SERVER 中（或者存储在header中）。

为了简化获取 traceId 的代码，我选择将其存储在 $_SERVER 中。这样，只需要通过 $_SERVER[‘traceId’] 就能够轻松获取到 traceId，而不需要编写繁琐的获取代码。相比之下，如果将 traceId 存储在请求体的 header 中，获取代码则需要写成 (Request::instance()->header())[‘traceId’] ?? “”。此外，如果系统中存在原生调用，需要获取所有的 header 头，就需要使用到 getallheaders() 函数。然而，getallheaders() 函数只能获取到最初请求打到服务上的所有 header 内容，而手动设置的 header 是无法被 getallheaders() 函数获取到的。因此，将 traceId 存储在 $_SERVER 中可以更加方便地获取，并且不受限于原生调用的影响

3. 添加到响应头中： 在响应头中添加 traceId。

<?php

namespace app\api\behavior;

/**
 * TraceId 行为类
 *
 * 此行为类用于在 API 请求的上下文中自动注入一个唯一的 traceId 到 HTTP 响应头。
 * traceId 主要用于链路追踪，有助于在日志中跟踪请求的全链路过程，
 * 提升系统问题排查和诊断的效率。
 */
class TraceId
{
    /**
     * 执行行为
     *
     * @return void
     */
    public function run()
    {
        // 使用generateTraceId()函数生成一个唯一的traceId值
        $traceId = generateTraceId();
        // 将生成的唯一traceId值存储在$_SERVER全局变量中
        $_SERVER['traceId'] = $traceId;
        // 设置响应头
        header("X-Trace-Id: {$traceId}");
    }
}

4. 处理异步请求： 在异步请求中，确保在发送请求时将 traceId 包含在请求头中。
发送请求

public function exec_bce($method, $post)
{
    $config = new \stdClass();
    $config->secret = 'dz_mufeng';
    $sign = $this->make_sign($post, $config);
    $traceId = $_SERVER['traceId'] ?? "";
    // 获取数据
    $content = http_build_query($post, '', '&');
    $header = [
        "Content-type:application/x-www-form-urlencoded",
        "Content-length:" . strlen($content),
        "traceId: " . $traceId
    ];
    $context['http'] = [
        'timeout' => 60,
        'method' => 'POST',
        'header' => implode("\r\n", $header),
        'content' => $content,
    ];
    $url = config('bce_url').'/code.php?method=' . $method . '&sign=' . $sign;
    log_write('code_exec_context:' . json_encode($context), 'info');
    $contextStream = stream_context_create($context);
    $res = file_get_contents($url, false, $contextStream);
    log_write("执行返回结果：" . $res, 'info');
    $res = preg_replace('/[\x00-\x1F\x80-\xFF]/', '', $res);
    $res = json_decode($res, true);
    if ($res['result'] == 0) {
        return $this->renderError($res['data']);
    } else {
        return $this->renderSuccess($res['data']);
    }

}

本系统原生代码在接收请求时，可直接使用 $_SERVER[‘HTTP_TRACEID’] 获取 traceId。

<?php
public function log($params, $type = 'info')
{
    if (!is_string($params)) {
        $params = json_encode($params, 320);
    }

    $requestId = $_SERVER['traceId'] ?? '';
    $traceId = $_SERVER['HTTP_TRACEID'] ?? "";

    !is_dir($this->logPath) && mkdir($this->logPath, 0755, true);

    $requestInfo = [
        '[trace_id]' => empty($traceId) ? $requestId : $traceId,
        '[request_ip]' => $this->getIp(),
        '[method]'     => $_SERVER['REQUEST_METHOD'],
        '[domain]'     => sprintf('%s://%s', $_SERVER['REQUEST_SCHEME'], $_SERVER['HTTP_HOST']),
        '[uri]'        => sprintf('%s://%s%s', $_SERVER['REQUEST_SCHEME'], $_SERVER['HTTP_HOST'], $_SERVER['REQUEST_URI']),
        '[param]'      => $params . "\r\n",
        '[trace]'      => (new \Exception)->getTraceAsString()
    ];

    $println = "---------------------------------------------------------------\r\n";
    $msg     = sprintf("%s%s [%s] ", $println, date("Y-m-d H:i:s"), $type);
    foreach ($requestInfo as $key => $value) {
        $msg .= sprintf("%s: %s ", $key, $value);
    }

    file_put_contents(sprintf("%s/%s_%s",
        $this->logPath, date("d"), "api.log"), $msg . "\r\n", FILE_APPEND);
}