去年冬天一个客户投诉,说他们后台的经营报表偶尔会转圈十几秒才出来。反馈很明确,问题是”偶尔”,抓不到规律。运维翻了半天日志,只看到几个 [error] 请求处理异常 的记录,堆栈指向一个第三方 SDK 的超时,除此之外没有别的信息。
麻烦在于,那条日志只说了”有一个请求失败了”,没说是哪个用户的、哪个接口的、请求了什么参数、数据库慢在哪一步。要到这些信息,只能重新触发一次问题复现。可这是个偶发问题,客户又不可能配合你反复操作。
那次之后,我把项目的异常和日志体系整体重构了一遍。今天把做法整理出来,给正在被”日志查不出问题”折磨的同行一份参考。
现有体系的三个盲点
重构之前先诊断一下原方案的问题。ThinkPHP 8 自带的异常处理和日志系统本身没问题,问题在于默认配置下它只覆盖了最基础的场景。真正的盲点有三个。
盲点一:日志里没有”请求身份”。每条日志是孤立的,看不出它们属于哪次请求。多用户并发时,同一个时间戳附近的日志混在一起,根本分不清哪些是同一个请求产生的。一个请求跨了五六个类、调了两三个外部接口、跑了十几次 DB 查询,这些动作之间没有任何关联标记。
盲点二:异常只有”记录”,没有”分级”。业务上”库存不足”和”数据库连不上”被一视同仁地记成 error。前者是正常的业务分支,后者才是系统级事故。混在一起之后,报警系统会被大量业务异常刷屏,真正重要的告警反而被淹没。
盲点三:日志是纯文本,没法聚合分析。默认格式是 [2025-01-01T10:23:45+08:00][error] xxx,人读着还行,但接入 ELK 或者 Loki 之后,想按用户 id 过滤、按接口路径聚合、按耗时排序全都做不到。这直接限死了线上分析的效率。
围绕这三个盲点,重构分四件事做。
第一件事:让 TraceId 流动起来
TraceId 是整套体系的地基。没有它,其他三件事都做不出效果。
生成的地点选在中间件里,因为中间件是整个请求生命周期里”还没进入业务代码”的最早位置。放在这里,后面所有环节都能拿到。
namespace appmiddleware;
use Closure;
use thinkfacadeLog;
use thinkRequest;
use thinkResponse;
use thinkfacadeApp;
class TraceId
{
public function handle(Request $request, Closure $next): Response
{
// 优先复用上游传过来的,支持链路追踪
$traceId = $request->header('X-Trace-Id');
if (!$traceId || !preg_match('/^[a-f0-9]{16,32}$/i', $traceId)) {
$traceId = $this->generate();
}
// 绑定到容器,业务代码可以随时取
app()->bind('trace_id', $traceId);
// 塞进日志的公共上下文
Log::withContext([
'trace_id' => $traceId,
'uri' => $request->url(),
'method' => $request->method(),
'ip' => $request->ip(),
]);
$response = $next($request);
// 响应头里带上,前端报错时能一起提交上来
return $response->header([
'X-Trace-Id' => $traceId,
'Server-Time' => date('c'),
]);
}
private function generate(): string
{
// 时间戳保证有序,随机段保证唯一
return sprintf('%08x%08x', time(), random_int(0, 0x7fffffff));
}
}
这段代码里有几个设计决策值得说。
为什么优先复用上游的。如果这个项目不是流量入口,上游服务(比如 Web 网关或者另一个微服务)已经生成了一个 TraceId,直接用它的能让整条链路可追踪。这是分布式链路追踪的基本要求,哪怕现在还没上 SkyWalking 之类的工具,习惯要提前养。
为什么要正则校验。Header 是用户可传的。如果直接把用户传进来的字符串当 TraceId 拼进日志,攻击者可以在里面塞换行符构造日志注入,在日志里伪造记录,或者塞进超长字符串把日志文件撑爆。八到三十二位十六进制字符的限制,是防止这类问题的第一道门。
为什么用时间戳加随机数。相比纯 UUID,时间前缀让 TraceId 天然有序,按日志时间排序时 TraceId 也跟着有序,排查问题时视觉上很舒服。不足部分用随机数填充,有效避免同一毫秒内的并发碰撞。
为什么在响应头里回传。这一条经常被忽略,但对排障价值很大。前端在页面上出异常时,能把 TraceId 一起上报给错误监控系统,你拿到的是一个精确指向某次请求的坐标,而不是”我记得下午三点多有个问题”。
第二件事:异常分级与响应策略
ThinkPHP 8 的异常处理入口在 appExceptionHandle,继承自 thinkexceptionHandle,核心方法是 render()。
namespace app;
use thinkdbexceptionDataNotFoundException;
use thinkdbexceptionModelNotFoundException;
use thinkexceptionHandle;
use thinkexceptionHttpException;
use thinkexceptionHttpResponseException;
use thinkexceptionValidateException;
use thinkfacadeLog;
use thinkResponse;
use Throwable;
class ExceptionHandle extends Handle
{
// 不用记日志的异常类型
protected $ignoreReport = [
HttpException::class,
HttpResponseException::class,
ValidateException::class,
DataNotFoundException::class,
ModelNotFoundException::class,
];
public function render($request, Throwable $e): Response
{
// 抽取分级信息
[$level, $code, $publicMessage] = $this->classify($e);
// 只记录需要记录的
if (!$this->isIgnored($e)) {
$this->logException($e, $level);
}
// 判断是否是 API 请求
if ($request->isJson() || $request->isAjax()) {
return $this->renderJson($e, $code, $publicMessage);
}
return parent::render($request, $e);
}
private function classify(Throwable $e): array
{
// 业务异常
if ($e instanceof appexceptionBusinessException) {
return ['warning', $e->getCode() ?: 40001, $e->getMessage()];
}
if ($e instanceof ValidateException) {
return ['info', 42200, $e->getMessage()];
}
if ($e instanceof HttpException) {
return ['info', $e->getStatusCode(), '请求错误'];
}
// 系统异常
return ['error', 50000, '服务器繁忙,请稍后再试'];
}
private function logException(Throwable $e, string $level): void
{
$context = [
'class' => get_class($e),
'file' => $e->getFile(),
'line' => $e->getLine(),
'code' => $e->getCode(),
'message' => $e->getMessage(),
'trace' => $this->getSimplifyTrace($e),
];
// 用动态方法根据 level 记日志
Log::record($e->getMessage(), $level, $context);
}
private function getSimplifyTrace(Throwable $e, int $limit = 8): array
{
$frames = [];
$count = 0;
foreach ($e->getTrace() as $frame) {
if ($count++ >= $limit) break;
$frames[] = sprintf(
'%s%s%s:%s',
$frame['class'] ?? '',
$frame['type'] ?? '',
$frame['function'] ?? '',
$frame['line'] ?? '?'
);
}
return $frames;
}
private function renderJson(Throwable $e, int $code, string $msg): Response
{
return json([
'code' => $code,
'msg' => $msg,
'data' => null,
'trace_id' => app()->get('trace_id'),
]);
}
}
几个关键点。
业务异常要单独建类
namespace appexception;
class BusinessException extends Exception
{
// 一个可选的公共错误码,跟 HTTP 状态码解耦
protected int $bizCode = 40001;
public static function make(string $message, int $code = 40001): self
{
$e = new self($message);
$e->bizCode = $code;
return $e;
}
public function getCode()
{
return $this->bizCode;
}
}
有了这个类,业务代码里”库存不足”这类正常的分支就可以这么写:
if ($stock < $qty) {
throw BusinessException::make('库存不足,仅剩 ' . $stock . ' 件', 50021);
}
好处有两个。一是业务异常可以统一走到 warning 级别,不触发严重告警,只看趋势;二是响应体里的错误码跟内部实现解耦,前端拿 50021 做针对性处理,也不需要知道 HTTP 状态码是 200 还是 400。
为什么忽略那几类异常
ValidateException 每次用户表单填错都会抛,DataNotFoundException 每次查空都会抛。这些异常不该写进日志,否则日志文件会被正常的业务流程迅速撑爆。
ThinkPHP 的 Handle 基类里有 $ignoreReport 数组,但是要注意——这个属性只影响基类的 report() 方法,不自动影响你重写的 render()。如果你在 render() 里手动打日志,还是得自己判断一次。所以上面代码里写了 isIgnored() 方法,逻辑是查一遍 $ignoreReport 数组。
不要把原始异常信息返给用户
renderJson() 里系统异常返回的固定是”服务器繁忙”,这是刻意为之。数据库表名、文件路径、SQL 语句这些信息一旦出现在响应体里,对攻击者就是情报。原始信息全部写进日志,让开发人员看。
环境区分很重要。开发环境下可以把原始异常渲染出来,方便调试;生产环境只返回通用的错误提示。这个判断用 app()->isDebug() 就能做。
第三件事:日志分级与切分
默认的单文件日志在生产环境是没法用的——问题一旦爆发,几分钟内就能把文件撑到几百 MB,不但读取慢,还容易撑爆磁盘。ThinkPHP 8 的日志支持通道(channel)配置,按业务域切分是首选方案。
// config/log.php
return [
'default' => 'app',
'channels' => [
// 应用主日志,日常业务
'app' => [
'type' => 'File',
'path' => runtime_path() . 'log/app',
'level' => ['info', 'notice', 'warning', 'error'],
'apart_level' => ['error'],
'max_files' => 30,
'json' => true,
'processor' => applogProcessor::class,
],
// 外部接口调用日志
'api' => [
'type' => 'File',
'path' => runtime_path() . 'log/api',
'level' => ['info'],
'max_files' => 7,
'json' => true,
'processor' => applogProcessor::class,
],
// 慢查询日志
'slow' => [
'type' => 'File',
'path' => runtime_path() . 'log/slow',
'level' => ['info'],
'max_files' => 7,
'json' => true,
'processor' => applogProcessor::class,
],
],
];
配置里有两个关键项。
apart_level:把 error 级别的日志单独存文件。这样排查生产事故的时候,直接 tail -f runtime/log/app/error.log,不用在混合了所有级别的大文件里翻找。
processor:一个回调类,每条日志写出之前都会被它加工一次。TraceId 的注入就在这里。
namespace applog;
class Processor
{
public function __invoke(array $record): array
{
// 补充公共上下文
$record['trace_id'] = app()->get('trace_id', '');
$record['host'] = gethostname();
$record['pid'] = getmypid();
// 敏感字段脱敏
if (isset($record['context'])) {
$record['context'] = $this->mask($record['context']);
}
return $record;
}
private function mask(array $context): array
{
static $sensitiveKeys = [
'password', 'passwd', 'pwd',
'token', 'access_token', 'refresh_token',
'id_card', 'bank_card', 'phone', 'mobile',
'secret', 'private_key',
];
foreach ($context as $key => $value) {
$lower = strtolower((string)$key);
foreach ($sensitiveKeys as $sensitive) {
if (str_contains($lower, $sensitive)) {
$context[$key] = '[MASKED]';
continue 2;
}
}
if (is_array($value)) {
$context[$key] = $this->mask($value);
} elseif (is_object($value) && method_exists($value, 'toArray')) {
$context[$key] = $this->mask($value->toArray());
}
}
return $context;
}
}
关于脱敏有几条经验。
先字符串化再匹配。有些字段名带业务前缀比如 user_password、old_pwd,用 str_contains 判断子串就都能覆盖到。用全等匹配会漏。
递归处理嵌套结构。业务上下文里经常有嵌套数组和对象,忘记递归会漏掉深层字段。上面代码里对 array 和 toArray 都做了递归。
不要只按字段名脱敏。有过一次事故,一个大数组以 items 为键传进来的,里面每项的 phone 字段全被记进了日志。字段名匹配不到 phone 是因为路径太深,但递归处理就抓到了。这也是为什么脱敏必须递归。
第四件事:外部接口调用日志
翻回开头那次报表卡顿。如果当时有外部接口调用的日志,问题会直观很多。做法是给所有外部调用加一个统一的包装函数:
namespace appsupport;
use thinkfacadeLog;
class Api
{
public static function request(string $service, string $url, array $options = []): array
{
$start = microtime(true);
$ch = curl_init($url);
curl_setopt_array($ch, [
CURLOPT_RETURNTRANSFER => true,
CURLOPT_TIMEOUT => $options['timeout'] ?? 5,
CURLOPT_CONNECTTIMEOUT => 3,
CURLOPT_HTTPHEADER => $options['headers'] ?? [],
]);
if (!empty($options['post'])) {
curl_setopt($ch, CURLOPT_POST, true);
curl_setopt($ch, CURLOPT_POSTFIELDS, $options['body'] ?? '');
}
$body = curl_exec($ch);
$errno = curl_errno($ch);
$errmsg = curl_error($ch);
$status = curl_getinfo($ch, CURLINFO_HTTP_CODE);
curl_close($ch);
$cost = (microtime(true) - $start) * 1000;
// 慢请求单独记到 slow 通道
if ($cost > 1000) {
Log::channel('slow')->info('slow api call', [
'service' => $service,
'url' => $url,
'cost_ms' => round($cost, 2),
'status' => $status,
]);
}
// 全部调用记到 api 通道
Log::channel('api')->info('api call', [
'service' => $service,
'url' => $url,
'cost_ms' => round($cost, 2),
'status' => $status,
'errno' => $errno,
'errmsg' => $errmsg,
'body_snippet' => mb_substr((string)$body, 0, 500),
]);
if ($errno) {
throw new RuntimeException("调用 {$service} 失败: {$errmsg}");
}
return json_decode($body, true) ?: [];
}
}
这个包装函数解决的正是开头那次事故的痛点。当时如果有人这么写,日志里就会有:
{"trace_id":"67a1b2c3...","service":"report-api","url":"...",
"cost_ms":14238.6,"status":504,"errno":28,"errmsg":"Operation timed out"}
一眼就能看出:哪个 TraceId 的请求、调哪个服务、多久返回、具体报什么错。有了 TraceId 还能反查同一个请求里的其他日志,完整还原整个请求链路。这就是文章开头强调”没有 TraceId 日志就只是文本”的原因。
慢请求阈值 1000ms 是一个保守值。真实项目里这个数字应该按业务定。报表类接口本身可能就要几秒,那就得放宽到 3000ms;实时性要求高的接口可能 500ms 就值得记录。别用一个标准套所有接口。
几处容易踩的坑
1. Log::withContext 在命令行里不生效
这是个很容易忽略的地方。Log::withContext() 依赖请求上下文,在常驻进程(Queue worker、Swoole)里行为不太一样。更稳妥的做法是把 TraceId 直接放进容器的绑定里,processor 从容器取,中间件负责在合适的时候 reset 掉。
// 中间件开头
app()->bind('trace_id', $traceId);
// 在常驻进程里,每次任务开始前重新绑定
app()->bind('trace_id', 'job-' . uniqid());
// processor 里
$record['trace_id'] = app()->get('trace_id', '');
2. 异常处理器里不要再抛异常
异常处理器应该是最后一道防线,任何在 render() 里抛出的异常都会导致 500 页面上显示 ThinkPHP 的默认错误页。日志写入本身也可能失败(磁盘满、权限错乱),所以日志调用最好用 try-catch 包一下:
try {
Log::record($e->getMessage(), $level, $context);
} catch (Throwable $inner) {
// 日志写不进去也不能让请求彻底挂掉
error_log('[FALLBACK] ' . $e->getMessage());
}
这种”兜底再兜底”的写法看着笨,但真出问题的时候能救回现场。
3. 慢日志通道会越积越多
慢日志如果按业务域命名文件(比如 slow-20250101.log),初期看着清晰,用久了会积累成百上千个文件。max_files 一定要配上,让日志自动轮转清理。生产环境还可以写一个定时任务,超过 N 天的日志直接归档到对象存储。
4. 敏感字段脱敏有遗漏路径
processor 只能处理日志上下文里显式传递的数据。如果业务代码有直接 Log::info('用户提交: ' . json_encode($all)) 这种写法,脱敏规则就绕过了。所以规约上要配合:
- 日志内容只允许用模板 + 上下文参数的形式,禁止字符串拼接
- 可以用 PHPStan 或者自定义 sniff 检查
Log::调用里有没有字符串拼接 - 真有必要输出大对象时,先手动脱敏或者只取几个关键字段
5. 响应头会被 Nginx 覆盖
在 Nginx 反代场景下,如果 gateway 或者 proxy 配置里写了 proxy_hide_header,自定义的 X-Trace-Id 可能被过滤掉,前端拿不到。上线之后立刻用 curl 在公网环境验证一下,看看响应头是不是真的透出去了。这个坑我当时踩过,本地和测试环境都对,一到生产前端就报”报错信息里没有 trace”。
最后
这四件事不是非得一次全上。按投入产出比排下来,我的建议顺序是:
先做 TraceId,一两个小时的事,收益立刻可见。以后再出线上问题,至少能用 TraceId 精确定位到某一次请求。
再做异常分级,一天之内能搞定。业务异常和系统异常分开之后,报警系统才真正能用——否则每次业务误操作都给你发报警邮件,运维会疯。
然后做日志切分,工作量稍大,但一次做好能用很久。apart_level 把 error 单独存这一条尤其值。
最后做外部调用日志。这个可以边用边加,把最常出问题的几个外部服务先包起来,其他的慢慢迁移。
做完之后,那次报表卡顿的问题就变成了”打开错误日志、搜 TraceId、看调用耗时”三步就能定位的事。整个体系的价值不在平时,而在于问题出现的那一刻——你不会再像当时那样,只能对着一条孤立的 error 日志发呆。

