问题背景
最近接手了一个骨灰级的项目,然而在项目中遇到了一个普遍的挑战:由于公司采用 ELK(Elasticsearch、Logstash、Kibana)作为日志收集和分析工具,追踪生产问题成为了一大难题。尽管 ELK 提供了强大的日志分析功能,但由于项目历史悠久,日志输出不规范,缺乏唯一标识,导致在海量日志中准确定位问题变得异常困难。为了提升生产环境下的问题排查和故障诊断效率,迫切需要在项目中引入一种机制,能够为每个请求生成唯一的标识符(traceId),并将其与 ELK 集成,以便在日志中准确追踪请求的全链路过程。
系统默认日志格式
elk 对这种格式采集并不太友好,所以打算重新写一个日志log类。
查看application/config.php配置文件,第一反应就是这个File到底在哪?OK,我们直接全局搜索 File.php,最终锁定文件路径:source/thinkphp/library/think/log/driver/File.php
基于自身业务改造,时间比较短哈,改写了一个初版(简单粗暴就是日志单行展示),可以短时间适配业务,改造后的代码如下:
<?phpnamespace 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。
<?phpnamespace 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,实现了请求的全链路追踪(包括异步请求,确保请求连贯性),从而提高了系统问题排查和诊断的效率。