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

最新推荐文章于 2025-08-28 13:25:34 发布
原创 最新推荐文章于 2025-08-28 13:25:34 发布 · 290 阅读 · 9 ·
CC 4.0 BY-SA版权
版权声明：本文为博主原创文章，遵循 CC 4.0 BY-SA 版权协议，转载请附上原文出处链接和本声明。
文章标签：

#java #logback

现象描述

错误日志：

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{
	...
	@Override
	public 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 stream
            closeOutputStream();

            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-139
            if (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 hierarchy
        if (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 里的日志输出去掉；（当然初始化等只执行一次的可以保留，但是每次输出日志时会触发的日志输出必须关掉）

根据问题现象、用户操作场景及日志打印去排查C++软件问题，必要时尝试去复现问题
dvlinker的技术专栏
11-03 2万+
根据问题现象、用户操作场景及日志打印去排查C++软件问题，必要时尝试去复现问题。
【C++软件调试技术】C++软件开发维护过程中典型软件异常问题的排查与总结
dvlinker的技术专栏
04-15 17万+
本文以问答的方式进行展开，罗列了C++软件日常开发和维护中遇到的多个软件调试问题及有代表性的场景，给出详细的处置思路和处理办法，以供大家借鉴和参考。
Selenium Grid
2401_87975790的博客
08-28 829
Selenium Grid 4 是一个分布式测试工具，支持在多浏览器、多平台上并行执行测试。它包含 Hub（中心节点）和 Node（工作节点）组件，提供三种部署方式：独立模式（快速启动）、Hub-Node 模式（经典分布式）、Docker 部署（推荐生产环境）。文章详细介绍了各模式的配置方法，并提供了兼容 Grid 的测试脚本示例（支持多浏览器并行测试）。此外还涵盖 Grid 管理监控、最佳实践、故障排除和高级特性（自定义节点配置、负载均衡）。通过合理使用 Selenium Grid，可显著提升测试效率和覆
Python 机器学习模型调试指南（一）
龙哥盟
08-28 1495
欢迎阅读 使用 Python 调试机器学习模型 – 您掌握机器学习的全面指南。本书旨在帮助您从机器学习的基本概念进步到专家级模型开发的复杂性，确保您的旅程既具有教育性又具有实用性。在本书中，我们超越了简单的代码片段，深入到构建可靠、工业级模型的整体过程。从模块化数据准备的细微差别到模型无缝集成到更广泛的技术生态系统中，每一章都是精心策划的，以弥合基本理解和高级专业知识之间的差距。我们的旅程不仅仅停留在模型创建上。我们将深入探讨评估模型性能、定位挑战，并为您提供有效的解决方案。强调在生产环境中引入和维护可靠模
CnOpenData全国彩票销售情况表
CnOpenData_wj的博客
08-28 559
2008.01-2025.4年度更新。
CnOpenData篮球游戏基本信息表
CnOpenData_wj的博客
08-28 490
2014.10.24-2024.8.25年度更新。
CnOpenData各地区彩票销售情况表
CnOpenData_wj的博客
08-28 431
2008.01-2025.4（2020年2月数据未披露）
C++软件调试与异常排查从入门到精通专栏介绍与文章汇总
热门推荐
dvlinker的技术专栏
06-29 22万+
根据近几年排查软件异常的实践与经验，系统地讲解了C++软件异常常见原因与常用排查方法，以图文并茂的方式给出具体的分析实例，带领大家逐步掌握C++软件异常排查的相关技术与要领。
任务死锁问题排查指南：4类常见场景、诊断工具使用与预防黄金法则
任务死锁问题的本质与影响 死锁是多任务系统中资源协调失控的典型表现，本质上源于多个执行单元因竞争资源而相互等待，导致永久性阻塞。其核心特征是所有涉及线程或进程均无法向前推进，系统整体陷入停滞状态。在...
如何捕获和记录SQL Server中发生的死锁
09-10
总结来说，捕获和记录SQL Server中的死锁对于排查问题和优化系统性能至关重要。通过启用适当的跟踪标志、设置警报和作业，或者使用服务器端跟踪，我们可以及时获取死锁事件的详细信息，从而采取相应措施避免或解决...
Go 机器学习项目（一）
龙哥盟
08-28 1102
Go 是机器学习的完美语言。其简单的语法有助于清晰地描述复杂算法，但不会让开发者无法理解如何运行高效优化的代码。这本书将教你如何在 Go 中实现机器学习，以创建易于部署和易于理解和调试的程序，同时还可以测量其性能。本书首先指导你使用 Go 库和功能设置机器学习环境。然后，你将深入分析一个真实的房屋定价数据集的回归分析，并在 Go 中构建一个分类模型来将电子邮件分类为垃圾邮件或正常邮件。
企业级CRM系统设计方案-配置清单和架构解析-主要服务于工业自动化产品的销售管理
qq_46108094的博客
08-27 1098
CRM客户关系管理系统技术架构概要：本系统采用Spring Boot+Vue.js技术栈构建，基于微服务架构设计。后端使用Spring Cloud Alibaba框架，包含认证、系统管理、CRM业务等8个微服务模块，集成MyBatis-Plus、Druid等组件，支持MySQL和SQL Server双数据库。前端基于Vue 2.x和Element UI，包含ECharts、Vxe-Table等业务组件。系统功能涵盖客户管理、销售订单、项目管理、财务结算等核心业务流程，提供完整的CRM解决方案。技术架构注重模
Tomato靶机Getshell到提权全流程！超详细！
weixin_61108159的博客
08-27 891
本文详细记录了渗透测试Tomato靶机的全过程。首先通过ARP扫描发现目标IP，使用nmap扫描发现开放21、80、2211、8888端口。在80端口的/antibot_image目录中发现存在文件包含漏洞，通过包含/etc/passwd文件验证漏洞。随后利用SSH服务将一句话木马写入日志文件，通过包含日志文件获取webshell。接着建立反向shell连接，并利用CVE-2017-6074漏洞进行提权尝试。在遇到GLIBC版本不兼容问题时，下载适配版本的libc库重新编译漏洞利用程序。整个渗透过程涉及信息
亚马逊机器学习高效指南（一）
龙哥盟
08-28 676
大数据和人工智能是我们日常生活中的普遍部分，催生了蓬勃发展的、价值数十亿美元的基于云的**机器学习即服务（MLaaS）**行业。在目前市场上众多的机器学习即服务（Machine Learning as a Service, MLaaS）平台中，亚马逊机器学习因其简单性而脱颖而出。亚马逊机器学习于 2015 年 4 月推出，其明确的目标是通过提供一种无需高度技术资源的公司也能访问的服务，降低预测分析门槛，同时平衡性能和成本。当与 AWS 生态系统的深度结合时，亚马逊机器学习平台使预测分析成为业务数据管道的自然
StarRocks架构演进：从经典架构到共享数据架构的变革
最新发布
gitblog_00857的博客
08-28 844
StarRocks架构演进：从经典架构到共享数据架构的变革 【免费下载链接】starrocks StarRocks是一个开源的分布式数据分析引擎，用于处理大规模数据查询和分析。 - 功能：分布式数据分析；大规模数据查询；数据分析；数据仓库。 - 特点：高性能；可扩展；易于使用；支持多种数据源。 ...
CnOpenData篮球游戏比赛积分榜表
CnOpenData_wj的博客
08-28 244
截至2024.8.24。
ElasticSearch健康检查localhost:9200 not reachable
u013205724的博客
06-23 1万+
项目场景： 项目使用了ElasticSearch【后续简称Es】，配置了Es的相关配置，通过spring的健康检查端点判断服务运行情况。项目未通过reactor的方式使用Es。 问题描述： 系统配置文件配置如下： ​​spring: elasticsearch: rest: uris: http://xxxx:9200,http://xxxx:9200,http://xxxx:9200 username: elastic password: ${pw
lombok未正常生效问题排查-maven编译问题排查
u013205724的博客
02-21 5638
问题报错-maven编译报错 [INFO] Scanning for projects... [INFO] [INFO] ------------------------------------------------------------------------ [INFO] Building Tailgate 1.0-SNAPSHOT [INFO] ------------------------------------------------------------------------ [INF
数据库死锁怎么排查
05-18
### 如何排查和解决数据库死锁问题 #### 死锁的定义与影响 死锁是指两个或多个事务相互等待对方释放资源，导致这些事务都无法继续执行的情况。这种情况会影响系统的并发性和响应速度，严重时可能导致整个应用的功能...
评论
添加红包

请填写红包祝福语或标题

个

红包个数最小为10个

元

红包金额最低5元

当前余额3.43元 前往充值 >
需支付：10.00元
成就一亿技术人!
领取后你会自动成为博主和红包主的粉丝 规则
hope_wisdom
发出的红包
实付元
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明：

1.余额是钱包充值的虚拟货币，按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载，可以购买VIP、付费专栏及课程。

余额充值