文档章节

记一次log4j与mongodb集成引发的问题分析

GeneKa
 GeneKa
发布于 2017/08/28 23:29
字数 1955
阅读 111
收藏 0
点赞 0
评论 0

问题背景

对项目中的关键应用调用链日志需要结构化得统一吐出到mongodb中,同时项目中日志输出使用log4j,故准备使用log4j的Appender直接集成mongodb的输出,同时mongodb采用集群模式。因为对于日志有特殊结构化要求,所以没有使用log4mongo库。

mongodb驱动版本:3.5.0

log4j版本:1.2.17

问题现象

error和warn级别的日志输出没有任何问题,但是当输出info级别日志的时候,保存失败,进程被阻塞,过一阵子后控制台报出如下:

Exception in thread "main" com.mongodb.MongoTimeoutException: Timed out after 30000 ms while waiting for a server that matches WritableServerSelector. Client view of cluster state is {type=UNKNOWN, servers=[{address=127.0.0.1:27017, type=UNKNOWN, state=CONNECTING}]

排查过程

  1. 首先查看mongodb进程和端口全部正常,并且切回warn和error级别再次输出后,一切正常,mongodb数据成功插入,排除了mongodb进程的原因。此步直接确定是log4j与mongodb集成驱动的原因

  2. 再次执行info级别输出,在进程无响应的时候,通过jstack拿取线程栈,发现尽然后线程阻塞引发的死锁。如下:main线程锁住了0x0000000797b8f4d0,而cluster-ClusterId再等待该锁的释放。

"cluster-ClusterId{value='59a3c74a936270211a375fc6', description='null'}-127.0.0.1:27017" #12 daemon prio=5 os_prio=31 tid=0x00007f97c2263800 nid=0x570f waiting for monitor entry [0x0000700001452000]
   java.lang.Thread.State: BLOCKED (on object monitor)
	at org.apache.log4j.Category.callAppenders(Category.java:202)
	- waiting to lock <0x0000000797b8f4d0> (a org.apache.log4j.spi.RootLogger)
	at org.apache.log4j.Category.forcedLog(Category.java:388)
	at org.apache.log4j.Category.log(Category.java:853)
	at org.slf4j.impl.Log4jLoggerAdapter.info(Log4jLoggerAdapter.java:300)
	at com.mongodb.diagnostics.logging.SLF4JLogger.info(SLF4JLogger.java:71)
	at com.mongodb.connection.InternalStreamConnection.open(InternalStreamConnection.java:110)
	at com.mongodb.connection.DefaultServerMonitor$ServerMonitorRunnable.run(DefaultServerMonitor.java:111)
	- locked <0x0000000797b01148> (a com.mongodb.connection.DefaultServerMonitor$ServerMonitorRunnable)
	
	
	
"main" #1 prio=5 os_prio=31 tid=0x00007f97c202f000 nid=0x1003 waiting on condition [0x0000700000182000]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x0000000797b03588> (a java.util.concurrent.CountDownLatch$Sync)
	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedNanos(AbstractQueuedSynchronizer.java:1037)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireSharedNanos(AbstractQueuedSynchronizer.java:1328)
	at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:277)
	at com.mongodb.connection.BaseCluster.selectServer(BaseCluster.java:114)
	at com.mongodb.binding.ClusterBinding$ClusterBindingConnectionSource.<init>(ClusterBinding.java:75)
	at com.mongodb.binding.ClusterBinding$ClusterBindingConnectionSource.<init>(ClusterBinding.java:71)
	at com.mongodb.binding.ClusterBinding.getWriteConnectionSource(ClusterBinding.java:68)
	at com.mongodb.operation.OperationHelper.withConnection(OperationHelper.java:413)
	at com.mongodb.operation.MixedBulkWriteOperation.execute(MixedBulkWriteOperation.java:168)
	at com.mongodb.operation.MixedBulkWriteOperation.execute(MixedBulkWriteOperation.java:74)
	at com.mongodb.Mongo.execute(Mongo.java:819)
	at com.mongodb.Mongo$2.execute(Mongo.java:802)
	at com.mongodb.MongoCollectionImpl.executeSingleWriteRequest(MongoCollectionImpl.java:550)
	at com.mongodb.MongoCollectionImpl.insertOne(MongoCollectionImpl.java:317)
	at com.mongodb.MongoCollectionImpl.insertOne(MongoCollectionImpl.java:307)
	at com.test.mongo.core.MongoLogAgent.saveLog(MongoLogAgent.java:52)
	at com.test.log.log4j.MongoAppender.append(MongoAppender.java:86)
	at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:230)
	- locked <0x0000000797b8f3e8> (a com.test.log.log4j.MongoAppender)
	at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:65)
	at org.apache.log4j.Category.callAppenders(Category.java:203)
	- locked <0x0000000797b8f4d0> (a org.apache.log4j.spi.RootLogger)
	at org.apache.log4j.Category.forcedLog(Category.java:388)
	at org.apache.log4j.Category.log(Category.java:853)	

3.测试代码及log4j.properties配置

private final static Logger logger = LoggerFactory.getLogger(Test.class);
public static void main(String[] args) throws Exception {
	logger.info("测试",new Exception("出错了"));
}
log4j.rootLogger=info,console,file,mongo
log4j.appender.mongo=com.test.log.log4j.MongoAppender

PS:mongo就是自己实现的Appender,因为没有实质性内容,就不再贴出,主要就是拿到日志后开始写入mongodb

4.既然找到了问题原因,直接看源码分析

log4j的Category对象中,会迭代循环Category及父节点,拿到之后对该对象进行加锁。synchronized(c)就是造成了上述线程栈中main线程(- locked <0x0000000797b8f4d0> (a org.apache.log4j.spi.RootLogger)的原因)

	AppenderAttachableImpl aai;
	//中间代码省略
    public void callAppenders(LoggingEvent event) {
        int writes = 0;
        for(Category c = this; c != null; c = c.parent) {
            synchronized(c) {
                if(c.aai != null) {
                    writes += c.aai.appendLoopOnAppenders(event);
                }

                if(!c.additive) {
                    break;
                }
            }
        }

        if(writes == 0) {
            this.repository.emitNoAppenderWarning(this);
        }

    }

根据log4j.properties的配置,MongoAppender对象,会在Log4j读取配置文件的时候加入到Category的aai对象中,此处appendLoopOnAppenders方法内就是循环执行console,file,mongo三个Appender的写方法,用来记录日志,其中MongoAppender中通过获取MongoClient进行insertDocument操作。

那cluster-ClusterId线程又是干什么的呢?

这个线程就是mongodb客户端驱动用来启动并且监听Socket链接并且建立连接池的一个独立线程,mongodb的客户端驱动在传入多个mongodb服务端ip并创建MongoClient对象时会构造MultiServerCluster对象及DefaultServer对象,该对象会绑定一个缺省的监听对象DefaultServerMonitor,DefaultServerMonitor对象在构造函数中,会初始化一个线程,这个线程就是真正建立mongodb数据库链接的地方。而DefaultServer对象在构造函数中负责启动该线程。当建立好链接后会将链接放入池中

	DefaultServer(final ServerId serverId, final ClusterConnectionMode clusterConnectionMode, final ConnectionPool connectionPool,
                  final ConnectionFactory connectionFactory, final ServerMonitorFactory serverMonitorFactory,
                  final ServerListener serverListener, final CommandListener commandListener) {
        this.serverListener = notNull("serverListener", serverListener);
        this.commandListener = commandListener;
        notNull("serverAddress", serverId);
        notNull("serverMonitorFactory", serverMonitorFactory);
        this.clusterConnectionMode = notNull("clusterConnectionMode", clusterConnectionMode);
        this.connectionFactory = notNull("connectionFactory", connectionFactory);
        this.connectionPool = notNull("connectionPool", connectionPool);
        this.serverStateListener = new DefaultServerStateListener();

        this.serverId = serverId;

        serverListener.serverOpening(new ServerOpeningEvent(this.serverId));

        description = ServerDescription.builder().state(CONNECTING).address(serverId.getAddress()).build();
        //构造并启动监控连接线程
        serverMonitor = serverMonitorFactory.create(serverStateListener);
        serverMonitor.start();
    }
//无关代码已注释
class DefaultServerMonitor implements ServerMonitor {
    DefaultServerMonitor(final ServerId serverId, final ServerSettings serverSettings,
                         final ChangeListener<ServerDescription> serverStateListener,
                         final InternalConnectionFactory internalConnectionFactory, final ConnectionPool connectionPool) {
        this.serverSettings = serverSettings;
        this.serverId = serverId;
        this.serverMonitorListener = getServerMonitorListener(serverSettings);
        this.serverStateListener = serverStateListener;
        this.internalConnectionFactory = internalConnectionFactory;
        this.connectionPool = connectionPool;
        monitor = new ServerMonitorRunnable();
        monitorThread = new Thread(monitor, "cluster-" + this.serverId.getClusterId() + "-" + this.serverId.getAddress());
        monitorThread.setDaemon(true);
        isClosed = false;
    }
    
    //一个内部类的线程,用于建立连接
    class ServerMonitorRunnable implements Runnable {
        private final ExponentiallyWeightedMovingAverage averageRoundTripTime = new ExponentiallyWeightedMovingAverage(0.2);

        @Override
        @SuppressWarnings("unchecked")
        public synchronized void run() {
            InternalConnection connection = null;
            try {
                ServerDescription currentServerDescription = getConnectingServerDescription(null);
                while (!isClosed) {
                    ServerDescription previousServerDescription = currentServerDescription;
                    try {
                        if (connection == null) {
                            connection = internalConnectionFactory.create(serverId);
                            try {
                                connection.open();
                            } catch (Throwable t) {
                                connection = null;
                                throw t;
                            }
                        }
                        try {
                            currentServerDescription = lookupServerDescription(connection);
                        } catch (MongoSocketException e) {
                            connectionPool.invalidate();
                            connection.close();
                            connection = null;
                            connection = internalConnectionFactory.create(serverId);
                            try {
                                connection.open();
                            } catch (Throwable t) {
                                connection = null;
                                throw t;
                            }
                            try {
                                currentServerDescription = lookupServerDescription(connection);
                            } catch (MongoSocketException e1) {
                                connection.close();
                                connection = null;
                                throw e1;
                            }
                        }
                    } catch (Throwable t) {
                        averageRoundTripTime.reset();
                        currentServerDescription = getConnectingServerDescription(t);
                    }

                    if (!isClosed) {
                        try {
                            logStateChange(previousServerDescription, currentServerDescription);
                            serverStateListener.stateChanged(new ChangeEvent<ServerDescription>(previousServerDescription,
                                    currentServerDescription));
                        } catch (Throwable t) {
                            LOGGER.warn("Exception in monitor thread during notification of server description state change", t);
                        }
                        waitForNext();
                    }
                }
            } finally {
                if (connection != null) {
                    connection.close();
                }
            }
        }
    }
}

可以看到mongodb驱动客户端是通过独立线程来建立连接的,而main线程中是操作的MongoClient对象,当主线程运行较快,MongoClient在执行insert获取不到连接时,会在BaseCluster类的selectServer方法中循环等待是否可以建立连接,若循环多次后时间超过了maxWaitTimeNanos,则直接抛出MongoTimeoutException,这就是为什么造成了超时现象,而mongodb驱动将真实原因屏蔽的地方,这样有个好处就是不会造成线程僵死,影响应用系统,但同时对人造成了误导。

public Server selectServer(final ServerSelector serverSelector) {
        isTrue("open", !isClosed());

        try {
            CountDownLatch currentPhase = phase.get();
            ClusterDescription curDescription = description;
            ServerSelector compositeServerSelector = getCompositeServerSelector(serverSelector);
            Server server = selectRandomServer(compositeServerSelector, curDescription);

            boolean selectionFailureLogged = false;

            long startTimeNanos = System.nanoTime();
            long curTimeNanos = startTimeNanos;
            long maxWaitTimeNanos = getMaxWaitTimeNanos();

            while (true) {
                throwIfIncompatible(curDescription);

                if (server != null) {
                    return server;
                }

                if (curTimeNanos - startTimeNanos > maxWaitTimeNanos) {
                    throw createTimeoutException(serverSelector, curDescription);
                }

                if (!selectionFailureLogged) {
                    logServerSelectionFailure(serverSelector, curDescription);
                    selectionFailureLogged = true;
                }

                connect();

                currentPhase.await(Math.min(maxWaitTimeNanos - (curTimeNanos - startTimeNanos), getMinWaitTimeNanos()), NANOSECONDS);

                curTimeNanos = System.nanoTime();

                currentPhase = phase.get();
                curDescription = description;
                server = selectRandomServer(compositeServerSelector, curDescription);
            }

        } catch (InterruptedException e) {
            throw new MongoInterruptedException(format("Interrupted while waiting for a server that matches %s", serverSelector), e);
        }
    }

死锁的产生

因为在log4j.propertis配置中,root上配置了所有的Appender。通过线程dump的分析和源码的解读,很容易发现是因为main线程在执行mongodb的Appender是,获取到的是rootLogger的锁,同时,BaseCluster类中每一次获取链接时利用了CountDownLatch方式将线程挂起,导致了主线程的等待,但此时main线程的锁并没有释放。而cluster-ClusterId线程中执行的mongodb代码中,通过slf4j也有Info级别的日志输出,而此时在执行Appender时,获取到的还是rootLogger对象,并又去申请该锁,因为是两个不同的线程,造成了cluster-ClusterId线程的阻塞

问题的解决

将mongodb包中的logger对象指向变为不是rootLogger即可,这样,cluster-ClusterId线程在获取Category对象锁时,与main线程已经申请到的对象锁不是同一个即可。

log4j.rootLogger=debug,console,file,mongo
#此配置是让org.mongodb的logger不继承父对象级别,即root,
log4j.additivity.org.mongodb=false
log4j.logger.org.mongodb=info,console

通过以上配置,所有org.mongodb包的日志,都会使用一个新的Logger对象,该对象只绑定了console一个Appender,此Logger对象的parent节点是rootLogger对象

	AppenderAttachableImpl aai;
	//中间代码省略
    public void callAppenders(LoggingEvent event) {
        int writes = 0;
        for(Category c = this; c != null; c = c.parent) {
        	//cluster-ClusterId线程中,此时加锁对象即为新的logger对象
            synchronized(c) {
                if(c.aai != null) {
                    writes += c.aai.appendLoopOnAppenders(event);
                }

                if(!c.additive) {
                    break;
                }
            }
        }

        if(writes == 0) {
            this.repository.emitNoAppenderWarning(this);
        }

    }

总结

网上也发现有log4j的死锁问题,其实跟多线程并发没什么关系,主要是一个线程在输出日志时,启动了另一个线程,但此时主线程又不释放锁,而子线程又去申请该锁导致的。

此时若是同一个线程,在synchronized(c)时,直接就是重入锁,不会产生死锁阻塞的问题。

© 著作权归作者所有

共有 人打赏支持
GeneKa
粉丝 2
博文 5
码字总数 6820
作品 0
杭州
架构师
Linux环境下将log4j的日志存储到mongoDB

单位有很多java项目,一般上生产的项目日志都是通过log4j打印在本地,平常开发同学要查看日志还要给他们开个专门的FTP,不利于集中维护管理,近日因工作需要,在网上看到相关技术资料,可把l...

基督山伯爵
2013/03/04
0
3
CentOS系统环境下安装MongoDB

原因:因为工作需要,集中管理log4j日志到MongoDB! 进入MongoDB下载中心:http://www.mongodb.org/downloads We recommend using these binary distributions (官方推荐使用二进制版本!) 根...

基督山伯爵
2013/03/01
0
1
简单的spring-data集成mongoDB项目,实现crud的功能

集成了spring框架的jar,加上三个spring-data的jar和一个驱动包 用IDE开发工具新建一个java 项目,需要spring框架的包,和spring-data需要的包,分别是 包下的三个包:spring-data-mongodb ,...

EDIAGD
2013/01/24
0
0
spring MVC 整合mongodb

Spring Mongodb 目录 1 SPRING整合MONGODB 1 1.1 环境准备 1 1.2 包依赖 1 1.3 配置 2 2 案列 5 2.1 SPRING MVC整合MONGODB代码案例 5 1 Spring整合Mongodb 1.1 环境准备 1. mongodb官网 ht...

浅夏
2014/03/13
0
0
windows下log4j日志存储到mongodb下

需求:系统做分布式,各个模块的日志写文件,对于运维来说找起日志来不方便,统一写到mongodb中,error级别的日志单独存储。 我的环境是win7 64位系统 第一步: 下载mongdb,下载地址: http...

凯文加内特
2015/10/27
0
6
55最佳实践系列:Logging最佳实践

@郑昀汇总 创建日期:2012/10 #意识 ASAP (As Soon As Possible)原则 当线上出现诡异问题, 当你意识到靠现有的日志无法定位问题时, 当现象难以在你的开发环境重现时, 请不要执著于枯坐肉眼...

旁观者-郑昀
2013/02/08
0
1
jdk-logging、log4j、logback日志介绍及原理

系列文章已完成,目录如下: - jdk-logging、log4j、logback日志介绍及原理- commons-logging与jdk-logging、log4j1、log4j2、logback的集成原理- slf4j与jdk-logging、log4j1、log4j2、log...

乒乓狂魔
2015/04/27
0
17
slf4j与jul、log4j1、log4j2、logback的集成原理

1 系列目录 - jdk-logging、log4j、logback日志介绍及原理- commons-logging与jdk-logging、log4j1、log4j2、logback的集成原理- slf4j与jdk-logging、log4j1、log4j2、logback的集成原理- s...

乒乓狂魔
2015/04/30
0
5
jcl与jul、log4j1、log4j2、logback的集成原理

1 系列目录 - jdk-logging、log4j、logback日志介绍及原理- jcl与jul、log4j1、log4j2、logback的集成原理- slf4j与jdk-logging、log4j1、log4j2、logback的集成原理- slf4j、jcl、jul、log...

乒乓狂魔
2015/04/29
0
2
jboss log4j冲突分析与解决

Log4j作为日志组件被大多数的系统所使用,Jboss也不例外的采用了Log4j作为它的日志输出组件。 但在使用JBoss时,很多人经常碰到一些冲突,这些冲如自己配置的log4j文件无效,系统抛org.jboss...

职通网
2012/07/16
0
0

没有更多内容

加载失败,请刷新页面

加载更多

下一页

SpringBoot | 第十章:Swagger2的集成和使用

前言 前一章节介绍了mybatisPlus的集成和简单使用,本章节开始接着上一章节的用户表,进行Swagger2的集成。现在都奉行前后端分离开发和微服务大行其道,分微服务及前后端分离后,前后端开发的...

oKong
今天
9
0
Python 最小二乘法 拟合 二次曲线

Python 二次拟合 随机生成数据,并且加上噪声干扰 构造需要拟合的函数形式,使用最小二乘法进行拟合 输出拟合后的参数 将拟合后的函数与原始数据绘图后进行对比 import numpy as npimport...

阿豪boy
今天
4
0
云拿 无人便利店

附近(上海市-航南路)开了家无人便利店.特意进去体验了一下.下面把自己看到的跟大家分享下. 经得现场工作人员同意后拍了几张照片.从外面看是这样.店门口的指导里强调:不要一次扫码多个人进入....

周翔
昨天
1
0
Java设计模式学习之工厂模式

在Java(或者叫做面向对象语言)的世界中,工厂模式被广泛应用于项目中,也许你并没有听说过,不过也许你已经在使用了。 简单来说,工厂模式的出现源于增加程序序的可扩展性,降低耦合度。之...

路小磊
昨天
176
1
npm profile 新功能介绍

转载地址 npm profile 新功能介绍 npm新版本新推来一个功能,npm profile,这个可以更改自己简介信息的命令,以后可以不用去登录网站来修改自己的简介了 具体的这个功能的支持大概是在6这个版...

durban
昨天
1
0
Serial2Ethernet Bi-redirection

Serial Tool Serial Tool is a utility for developing serial communications, custom protocols or device testing. You can set up bytes to send accordingly to your protocol and save......

zungyiu
昨天
1
0
python里求解物理学上的双弹簧质能系统

物理的模型如下: 在这个系统里有两个物体,它们的质量分别是m1和m2,被两个弹簧连接在一起,伸缩系统为k1和k2,左端固定。假定没有外力时,两个弹簧的长度为L1和L2。 由于两物体有重力,那么...

wangxuwei
昨天
0
0
apolloxlua 介绍

##项目介绍 apolloxlua 目前支持javascript到lua的翻译。可以在openresty和luajit里使用。这个工具分为两种模式, 一种是web模式,可以通过网页使用。另外一种是tool模式, 通常作为大规模翻...

钟元OSS
昨天
2
0
Mybatis入门

简介: 定义:Mybatis是一个支持普通SQL查询、存储过程和高级映射的持久层框架。 途径:MyBatis通过XML文件或者注解的形式配置映射,实现数据库查询。 特性:动态SQL语句。 文件结构:Mybat...

霍淇滨
昨天
2
0
开发技术瓶颈期,如何突破

前言 读书、学习的那些事情,以前我也陆续叨叨了不少,但总觉得 “学习方法” 就是一个永远在路上的话题。个人的能力、经验积累与习惯方法不尽相同,而且一篇文章甚至一本书都很难将学习方法...

_小迷糊
昨天
1
0

没有更多内容

加载失败,请刷新页面

加载更多

下一页

返回顶部
顶部