问题背景
最近接手了一个骨灰级的项目，然而在项目中遇到了一个普遍的挑战：由于公司采用 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);
}
结论
以上解决方案有效地为 ThinkPHP5 的日志添加了 traceId，实现了请求的全链路追踪（包括异步请求，确保请求连贯性），从而提高了系统问题排查和诊断的效率。
