当前位置： 首页 > news >正文

日志输出触发的死锁问题排查记录

news 2025/8/29 9:20:55

现象描述

错误日志：

Found one Java-level deadlock:
=============================
"http-nio-8083-exec-106":waiting for ownable synchronizer 0x00000005cbfa6b90, (a java.util.concurrent.locks.ReentrantLock$NonfairSync),which is held by "http-nio-8083-exec-10"
"http-nio-8083-exec-10":waiting for ownable synchronizer 0x00000005cbf7e808, (a java.util.concurrent.locks.ReentrantLock$NonfairSync),which is held by "http-nio-8083-exec-6"
"http-nio-8083-exec-6":waiting for ownable synchronizer 0x00000005cbfa6b90, (a java.util.concurrent.locks.ReentrantLock$NonfairSync),which is held by "http-nio-8083-exec-10"Java stack information for the threads listed above:
===================================================
"http-nio-8083-exec-106":at sun.misc.Unsafe.park(Native Method)- parking to wait for  <0x00000005cbfa6b90> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:209)at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:210)at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:100)at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84)at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51)at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270)at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257)at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:421)at ch.qos.logback.classic.Logger.filterAndLog_1(Logger.java:398)at ch.qos.logback.classic.Logger.info(Logger.java:583)...
"http-nio-8083-exec-10":at sun.misc.Unsafe.park(Native Method)- parking to wait for  <0x00000005cbf7e808> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:209)at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:210)at ch.qos.logback.core.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:235)at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:100)at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84)at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51)at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270)at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257)at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:421)at ch.qos.logback.classic.Logger.filterAndLog_1(Logger.java:398)at ch.qos.logback.classic.Logger.warn(Logger.java:696)at cn.com.xxx.xxx.xxx.log.desensitization.core.SensitHelper.doInforFilter(SensitHelper.java:109)at cn.com.xxx.xxx.xxx.log.desensitization.logback.MaskingPatternLayout.doLayout(MaskingPatternLayout.java:64)at cn.com.xxx.xxx.xxx.log.desensitization.logback.MaskingPatternLayout.doLayout(MaskingPatternLayout.java:23)at ch.qos.logback.core.encoder.LayoutWrappingEncoder.doEncode(LayoutWrappingEncoder.java:130)at ch.qos.logback.core.OutputStreamAppender.writeOut(OutputStreamAppender.java:187)at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:212)at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:100)at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84)at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51)at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270)at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257)at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:421)at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:383)at ch.qos.logback.classic.Logger.error(Logger.java:538)...
"http-nio-8083-exec-6":at sun.misc.Unsafe.park(Native Method)- parking to wait for  <0x00000005cbfa6b90> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:209)at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:210)at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:100)at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84)at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51)at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270)at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257)at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:421)at ch.qos.logback.classic.Logger.filterAndLog_1(Logger.java:398)at ch.qos.logback.classic.Logger.warn(Logger.java:696)at cn.com.xxx.xxx.xxx.log.desensitization.core.SensitHelper.doInforFilter(SensitHelper.java:109)at cn.com.xxx.xxx.xxx.log.desensitization.logback.MaskingPatternLayout.doLayout(MaskingPatternLayout.java:64)at cn.com.xxx.xxx.xxx.log.desensitization.logback.MaskingPatternLayout.doLayout(MaskingPatternLayout.java:23)at ch.qos.logback.core.encoder.LayoutWrappingEncoder.doEncode(LayoutWrappingEncoder.java:130)at ch.qos.logback.core.OutputStreamAppender.writeOut(OutputStreamAppender.java:187)at ch.qos.logback.core.FileAppender.writeOut(FileAppender.java:279)at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:212)at ch.qos.logback.core.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:235)at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:100)at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84)at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51)at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270)at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257)at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:421)at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:383)at ch.qos.logback.classic.Logger.error(Logger.java:538)...

MaskingPatternLayout代码：

@Slf4j
public class MaskingPatternLayout extends PatternLayout{...@Overridepublic String format(LoggingEvent e){...满足特定情况时会执行日志输出。LOGGER.warn("xxxxx")...}...
}

环境信息

logback版本：1.1.11

初步分析

堆栈中出现的代码，有部分是我们自己定制的日志脱敏逻辑。
重点分析自己写的代码：MaskingPatternLayout。
首先lock是OutputStreamAppender中的，检查相关代码lock（可重入锁）逻辑。

public void setOutputStream(OutputStream outputStream) {lock.lock();try {// close any previously opened output streamcloseOutputStream();this.outputStream = outputStream;if (encoder == null) {addWarn("Encoder has not been set. Cannot invoke its init method.");return;}encoderInit();} finally {lock.unlock();}}......public void stop() {lock.lock();try {closeOutputStream();super.stop();} finally {lock.unlock();}}......protected void subAppend(E event) {if (!isStarted()) {return;}try {// this step avoids LBCLASSIC-139if (event instanceof DeferredProcessingAware) {((DeferredProcessingAware) event).prepareForDeferredProcessing();}// the synchronization prevents the OutputStream from being closed while we// are writing. It also prevents multiple threads from entering the same// converter. Converters assume that they are in a synchronized block.lock.lock();try {writeOut(event);} finally {lock.unlock();}} catch (IOException ioe) {// as soon as an exception occurs, move to non-started state// and add a single ErrorStatus to the SM.this.started = false;addStatus(new ErrorStatus("IO failure in appender", this, ioe));}}......protected void writeOut(E event) throws IOException {this.encoder.doEncode(event);}

可以看到lock的操作没有任何问题。肯定能释放锁。那为什么还会锁住呢？

进一步分析writeOut方法，这里会调用到我们自定义的日志脱敏逻辑。
日志脱敏逻辑我们可以确定绝对不会死锁。（唯一特殊的就是他在里面输出了日志）

进一步分析logback的实现逐行排查,根据堆栈信息找到 Logger 类如下关键代码：

    /*** Invoke all the appenders of this logger.* * @param event*          The event to log*/public void callAppenders(ILoggingEvent event) {int writes = 0;for (Logger l = this; l != null; l = l.parent) {writes += l.appendLoopOnAppenders(event);if (!l.additive) {break;}}// No appenders in hierarchyif (writes == 0) {loggerContext.noAppenderDefinedWarning(this);}}

AppenderAttachableImpl 类的关键代码：

public int appendLoopOnAppenders(E e) {int size = 0;final Appender<E>[] appenderArray = appenderList.asTypedArray();final int len = appenderArray.length;for (int i = 0; i < len; i++) {appenderArray[i].doAppend(e);size++;}return size;}

从上面可以看出，在执行日志输出时，会找到所有可用的Appender执行日志输出。

而锁住的线程又是都在执行loop循环的时候卡住的。
那么会不会是因为是日志输出导致的呢？

死锁复现

尝试让程序多线程都触发日志脱敏时的日志输出逻辑；
发现死锁复现；

根因定位

在多线程环境下，如果日志Layout实现里又打印了日志。
假设日志使用了RollingAppender 和 ConsoleAppender 就会产生如下情况：
ThreadA:
执行RollingAppender（占用RollingAppender锁）->Layout输出日志->执行RollingAppender（可重入，因此可以获取锁）->执行ConsoleAppender（申请锁）
ThreadB:
执行ConsoleAppender（占用ConsoleAppender锁）->Layout输出日志->->执行RollingAppender（申请锁）
两个线程分别占用了一个锁，并申请对方的锁。满足死锁条件：
1）互斥条件：Appender可重入锁，ThreadA和ThreadB互斥;
2）请求和保持条件：ThreadA占用RollingAppender申请ConsoleAppender，ThreadB相反;
3）不剥夺条件：ThreadA无法剥夺ThreadB的锁;
4）环路等待条件：ThreadA占用RollingAppender申请ConsoleAppender，ThreadB相反;

解决方案

不要在日志输出处理逻辑里面再次触发日志输出；
也就是把 MaskingPatternLayout 里的日志输出去掉；（当然初始化等只执行一次的可以保留，但是每次输出日志时会触发的日志输出必须关掉）

http://www.dtcms.com/a/353139.html

相关文章：

  • Android 中 spinner / AppCompatSpinner 文字颜色 和 显示样式 源码分析
  • 如何轻松地将数据从安卓设备传输到安卓设备
  • 构建AI智能体：十五、超越关键词搜索：向量数据库如何解锁语义理解新纪元
  • 使用 html2canvas + jspdf 实现页面元素下载为pdf文件
  • Transformer 模型在自动语音识别（ASR）中的应用
  • 华为L420国产笔记本（统信UOS桌面专业版1070）安装openEuler2403虚拟机
  • 基于Spring Boot的民宿服务管理系统-项目分享
  • Python 并行计算进阶：ProcessPoolExecutor 处理 CPU 密集型任务
  • Java设计模式之《外观模式》
  • 广东省省考备考（第八十八天8.27）——判断推理（第八节课）
  • 31. 什么是字符串常量池
  • 2025.8.27链表_链表逆置
  • 【Python-1】字符串连接方式“+“和“，”的区别
  • AI + 旅游 = 应用案例分析（一）
  • TDengine IDMP 5 个实测场景让监控变简单
  • 【和春笋一起学C++】（三十七）类的析构函数
  • rust语言（1.88.0）sqlite数据库rusqlite库（0.37.0）学习笔记
  • Linux 服务器故障全解析：常见问题及处理方法大全
  • 极简风格PDF格式转换解决方案
  • java将doc文件转pdf
  • PDF补丁丁：开源多年，完全免费的多功能 PDF 工具箱
  • Magicodes.IE.Pdf 生成导出PDF文件 bytes Stream FileStreamResult 下载
  • 像WPS Office 一样处理pdf页面尺寸
  • OpenGL 视差贴图
  • UVa11607 Cutting Cakes
  • Java垃圾回收器：从SerialGC到G1的演进/速通
  • 流程控制语句（1）
  • 如何检查 Linux 系统的内存使用情况
  • vue2实现背景颜色渐变
  • 【目标检测】论文阅读4