生产环境排查重复消费问题,明明代码里 catch 住了异常并打了 log.warn,却在日志文件里死活找不到。控制台输出又因容器化部署而丢失,问题久久无法定位。本文记录一次真实排查过程,根因出在 logback 的 root logger 与 biz logger 配置差异上。
一、问题背景
kafka 消费者接收设备事件消息后,需要落库到本地 device_event_message 表。该表的 msg_service_business_id 字段上有唯一索引,用于防止 kafka 重复消费导致的数据重复。
代码逻辑很标准:try 里执行 insert,catch (exception e) 里 log.warn 打印日志并吞掉异常,不阻断后续推送流程。
@service
@slf4j
public class bizmsgserviceimpl {
@kafkalistener(topics = "${kafka.consumer.deviceeventtopic}", ...)
public void kafkadeviceeventlisten(consumerrecord<string, string> record) {
// ... 解析事件 ...
string msgservicebusinessid = event.getdeviceid() + "_" + event.getdevicesn() + "_" + event.getoccurtime();
// 保存到本地设备事件表
savedeviceeventmessage(event, containerid, msgservicebusinessid);
// ... 后续推送消息中心 ...
logutils.biz.info("发送设备事件消息=> {}", collections.singletonlist(msginforeqdto));
msginfoservice.savamsginfopos(collections.singletonlist(msginforeqdto));
}
/**
* 将kafka设备事件保存到本地设备事件表
* business_id 存在唯一索引,重复事件插入失败时仅告警不阻断
*/
private void savedeviceeventmessage(deviceevententity event, string containerid, string businessid) {
try {
deviceeventmessagepo po = new deviceeventmessagepo();
// ... set 各字段 ...
deviceeventmessagemapper.insert(po);
} catch (exception e) {
log.warn("保存设备事件到本地表失败 businessid={}", businessid, e);
}
}
}
二、问题现象
线上一段时间后,用户反馈偶发重复推送。排查时翻遍 warn.log、error.log 文件,没有找到任何 保存设备事件到本地表失败 的日志。
但数据库里又能查到唯一索引冲突的痕迹(或通过其他途径确认确实发生了重复消费)。于是陷入"明明打了日志却找不到"的困境。
三、根因分析
3.1 第一反应:日志级别?
第一反应是怀疑 log.warn 级别在生产环境被调高过滤了。但查看 logback-spring.xml:
<root level="info">
<appender-ref ref="stdout"/>
<appender-ref ref="async_info"/>
<appender-ref ref="async_error"/>
</root>root level="info",warn 级别高于 info,级别上不会被过滤。这条路走不通。
3.2 第二反应:异常没抛出?
怀疑 insert 违反唯一约束时没有抛异常。但 mybatis-plus 的 basemapper.insert 执行的是标准 insert into,mysql 唯一索引冲突会立即抛 sqlexception,经 mybatis 包装为 persistenceexception,再经 spring 包装为 duplicatekeyexception。这些异常都会被 catch (exception e) 捕获。
而且即使不抛异常,log.warn 这行代码至少会被执行(除非异常发生在 catch 之前)。所以异常没抛出也不是根因。
3.3 真相:root logger 没有 async_warn
仔细对比 logback-spring.xml 中 root logger 和 biz logger 的 appender 配置:
<!-- root logger:只挂了 stdout、async_info、async_error,没有 async_warn! -->
<root level="info">
<appender-ref ref="stdout"/>
<appender-ref ref="async_info"/>
<appender-ref ref="async_error"/>
</root>
<!-- biz logger:挂了 async_warn -->
<logger name="biz" level="debug" additivity="false">
<appender-ref ref="stdout"/>
<appender-ref ref="async_info"/>
<appender-ref ref="async_debug"/>
<appender-ref ref="async_warn"/>
<appender-ref ref="async_error"/>
</logger>再看各文件 appender 的 filter 配置——用的是 levelfilter 精确匹配:
<appender name="warn" class="ch.qos.logback.core.rolling.rollingfileappender">
<filter class="ch.qos.logback.classic.filter.levelfilter">
<level>warn</level>
<onmatch>accept</onmatch>
<onmismatch>deny</onmismatch> <!-- 非 warn 一律拒绝 -->
</filter>
<file>${logpath}/log/warn.log</file>
...
</appender>
<appender name="info" class="ch.qos.logback.core.rolling.rollingfileappender">
<filter class="ch.qos.logback.classic.filter.levelfilter">
<level>info</level>
<onmatch>accept</onmatch>
<onmismatch>deny</onmismatch> <!-- warn 会被拒绝,不进 info.log -->
</filter>
...
</appender>3.4 两个 logger 的行为差异
关键在于代码里用了哪个 logger:
| 调用方式 | logger 名称 | 走的 logger 配置 | warn.log | info.log | 控制台 stdout |
|---|---|---|---|---|---|
log.warn(...)(@slf4j 注入) | com.dsa.hems.msg.service.bizmsgserviceimpl | root | ❌ 不写入 | ❌ levelfilter 拒绝 warn | ✅(但容器易丢失) |
logutils.biz.warn(...) | biz | biz logger | ✅ 写入 | ❌ | ✅ |
// logutils.java
public interface logutils {
logger biz = loggerfactory.getlogger("biz");
}
savedeviceeventmessage 用的是 log.warn(走 root logger),而同一个 kafkalistener 方法里其他业务日志用的都是 logutils.biz.info(走 biz logger)。
root logger 没有挂载 async_warn appender,所以 log.warn 的输出:
- ❌ 不写入
warn.log(只有 biz logger 才挂了 async_warn) - ❌ 不写入
info.log(info appender 的 levelfilter 精确匹配 info,warn 被 deny) - ❌ 不写入
error.log(同理) - ✅ 只输出到控制台 stdout
而生产环境是 docker 容器部署,控制台日志不落盘、易丢失,排查时只看文件日志,自然就"找不到日志"了。
3.5 一次完整的调用链对照
@kafkalistener(...)
public void kafkadeviceeventlisten(consumerrecord<string, string> record) {
logutils.biz.info("监听到设备事件消息 {} ", value); // ✅ 走 biz,写 info.log
// ...
savedeviceeventmessage(...); // ⚠️ 内部用 log.warn,走 root
// ...
logutils.biz.info("发送设备事件消息=> {}", ...); // ✅ 走 biz,写 info.log
}
private void savedeviceeventmessage(...) {
try {
deviceeventmessagemapper.insert(po);
} catch (exception e) {
log.warn("保存设备事件到本地表失败 ...", e); // ❌ 走 root,不写任何文件
}
}
同一个方法里,biz logger 和 @slf4j 的 log 混用,正是这次踩坑的直接原因。
四、解决方案
4.1 方案一(推荐):统一使用 biz logger
把 log.warn 改成 logutils.biz.warn,与同方法其他日志保持一致:
private void savedeviceeventmessage(deviceevententity event, string containerid, string businessid) {
try {
deviceeventmessagepo po = new deviceeventmessagepo();
po.setmsgservicebusinessid(businessid);
// ... set 各字段 ...
deviceeventmessagemapper.insert(po);
} catch (duplicatekeyexception e) {
// 唯一索引冲突:kafka重复消费或同businessid事件重复推送,属于预期场景,仅告警不阻断
logutils.biz.warn("设备事件重复插入(唯一索引冲突), businessid={}, devicesn={}, eventtype={}, occurtime={}",
businessid, event.getdevicesn(), event.geteventtype(), event.getoccurtime());
} catch (exception e) {
logutils.biz.warn("保存设备事件到本地表失败, businessid={}, devicesn={}, eventtype={}",
businessid, event.getdevicesn(), event.geteventtype(), e);
}
}
补充说明:
duplicatekeyexception来自org.springframework.dao,mybatis-plus-boot-starter会传递引入spring-tx,可放心使用。- 对唯一索引冲突这种预期场景不打印异常堆栈(避免日志噪音,只打关键字段);对其他未知异常打印完整堆栈,方便排查。
4.2 方案二:给 root logger 补上 async_warn
从 logback 配置层面兜底,让所有走 root 的 warn 日志都能落盘:
<root level="info">
<appender-ref ref="stdout"/>
<appender-ref ref="async_info"/>
<appender-ref ref="async_warn"/> <!-- 补上这一行 -->
<appender-ref ref="async_error"/>
</root>建议两个方案都做:方案一统一编码规范,方案二兜底防止其他类再踩坑。
4.3 不推荐的写法
// ❌ 用 @slf4j 的 log,走 root logger,warn 不落盘
log.warn("保存设备事件到本地表失败 businessid={}", businessid, e);
// ❌ 异常被吞但无任何日志
} catch (exception e) {
// 啥也不干
}
五、延伸:levelfilter vs thresholdfilter
这次踩坑还暴露一个易混淆点——levelfilter 与 thresholdfilter 的区别:
| 过滤器 | 行为 | warn 日志能否进入 info appender |
|---|---|---|
levelfilter(onmatch=accept, onmismatch=deny) | 精确匹配指定级别,其他一律 deny | ❌ 不会(warn ≠ info) |
thresholdfilter(level=info) | 大于等于指定级别都通过 | ✅ 会(warn ≥ info) |
本项目用的是 levelfilter 精确匹配,所以 info.log 里只有 info,warn.log 里只有 warn。这种"按级别分文件"的设计本身没问题,但前提是 logger 必须挂载对应的 appender,否则该级别的日志就无处可去。
六、总结与避坑清单
- 同一个类里不要混用
log(@slf4j)和logutils.biz:二者走不同 logger 配置,行为差异巨大。统一用业务约定的 logger(本项目是logutils.biz)。 - 改 logback 配置后,确认 root logger 挂载了所有需要的级别 appender:尤其是
async_warn,否则所有走 root 的 warn 日志只在控制台,不落盘。 - 生产环境务必保留容器控制台日志:用
docker logs或挂载 volume 收集 stdout,作为文件日志的兜底。 - 区分"预期异常"与"未知异常":唯一索引冲突是可预期的,单独 catch 并精简日志(不打堆栈);其他异常打印完整堆栈。这样既不淹没真正的问题,又不丢失排查线索。
- catch 块的日志要带足够上下文:本次修复补充了
devicesn、eventtype、occurtime等字段,便于从日志直接定位是哪台设备、哪类事件重复。
一句话避坑:log.warn 不一定写进 warn.log——取决于你用的是哪个 logger、它挂了哪些 appender。
到此这篇关于springboot中logback日志丢失原因排查与解决方法的文章就介绍到这了,更多相关springboot logback日志丢失内容请搜索代码网以前的文章或继续浏览下面的相关文章希望大家以后多多支持代码网!
发表评论