跳至主要內容

日志追踪(qilu-logTrace)介绍

senvon大约 5 分钟启路日志追踪框架详解

日志追踪(qilu-logTrace)介绍

logTrace是在排错的时候,查询服务器日志的时候冒出来的需求.一旦一个应用被部署到服务器上以后,在应用的手段内,就只能看到日志情况,而日志本身会受到多线程并发的影响,在并发比较大的情况下,排查一个线程的执行情况,如果没有一个traceKey作为查询条件的话,会面临一种很无力的局面.

logTrace最大的想法,是结合linux的grep命令,在最小侵入开发的情况下,最大程度的提供日志查询的简洁---通过2组grep命令,来实现查看某一个线程的所有日志.

代码集成

maven依赖

logback集成请引入
<dependency>
	<groupId>com.9istock.base</groupId>
	<artifactId>qilu-logtrace-logback</artifactId>
	<version>1.0.0</version>
</dependency>
log4j集成,请引入
<dependency>
	<groupId>com.9istock.base</groupId>
	<artifactId>qilu-logtrace-log4j</artifactId>
	<version>1.0.0</version>
</dependency>

日志配置

logback的日志配置,需要加上encoder的配置,特殊定义pattern
<property name="default_pattern" value="%d [%t - %X{traceNo}] %-5level %c{1} - %m%n" />
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
	<encoder class="com.istock.base.logtrace.logback.encoder.TraceNoPatternLayoutEncoder">
		<charset>UTF-8</charset>
		<pattern>${default_pattern}</pattern>
	</encoder>
</appender>
	
log4j的日志配置,直接配置pattern
<appender name="CONSOLE-APPENDER" class="org.apache.log4j.ConsoleAppender">
	<param name="encoding" value="UTF-8" />
	<layout class="com.istock.base.logtrace.log4j.encoder.TraceNoPatternLayout">
		<param name="ConversionPattern" value="%d %p [%t - %X{traceNo}] %c{2} - %m%n" />
	</layout>
</appender>

使用

web.xml配置

如果希望在所有的服务端controller中加入trace日志,在所有服务端请求中增加过滤器,在日志中间件中加入trace

<filter>
	<filter-name>traceNoFilter</filter-name>
	<filter-class>com.istock.base.logtrace.filter.TraceNoFilter</filter-class>
</filter>

<filter-mapping>
	<filter-name>traceNoFilter</filter-name>
	<url-pattern>*.do</url-pattern>
</filter-mapping>

使用上述配置,应用程序会在controller的入口,加入日志的trace信息

应用程序正常使用log组件输出

在整个线程堆栈里面都会打印出相同的trace

  1. 2019-08-27 13:52:23,532 [atomic-task-asyn-1 - uLVPoWmpHm4Q] INFO c.i.b.a.s.AutoTaskService - to lock task taskType[CLEAR_ONLINE],taskNo[20190827135323],taskState[WAITING_EXECUTE],curExecTime[null],curExecutor[null]
  2. 2019-08-27 13:52:23,690 [atomic-task-asyn-1 - uLVPoWmpHm4Q] DEBUG c.i.b.a.d.AutoTaskDAO - =======update by selective:UPDATE SYS_AUTO_TASK SET TASK_NO=:taskNo,TASK_TYPE=:taskType,CUR_EXECUTOR=:curExecutor,LAST_EXEC_TIME=:lastExecTime,LAST_EXECUTOR=:lastExecutor,EXECUTED_TIMES=:executedTimes,TASK_STATE=:taskState,UPDATE_TIME=:updateTime WHERE TASK_NO=:taskNo AND TASK_TYPE=:taskType AND TASK_STATE <> :notTaskState AND CUR_EXECUTOR IS NULL =====
  3. 2019-08-27 13:52:23,690 [atomic-task-asyn-1 - uLVPoWmpHm4Q] DEBUG c.i.b.a.d.AutoTaskDAO - ==========updateByExample paramMap :{lastExecutor=3164@MicroWin10-1452|130.252.10.0|atomic-task-asyn-1|30, serialVersionUID=1, taskType=CLEAR_ONLINE, taskState=EXECUTING, executedTimes=1, taskNo=20190827135323, curExecutor=3164@MicroWin10-1452|130.252.10.0|atomic-task-asyn-1|30, updateTime=Tue Aug 27 13:52:23 CST 2019, lastExecTime=Tue Aug 27 13:52:23 CST 2019, notTaskState=COMPLETE, moreLastExecedTime=null}
  4. 2019-08-27 13:52:23,691 [atomic-task-asyn-1 - uLVPoWmpHm4Q] INFO c.i.b.a.s.AutoTaskService - locked task taskType[CLEAR_ONLINE],taskNo[20190827135323] by 3164@MicroWin10-1452|130.252.10.0|atomic-task-asyn-1|30
  5. 2019-08-27 13:52:23,725 [atomic-task-asyn-1 - uLVPoWmpHm4Q] INFO c.i.u.u.t.UserOnlineTask - ready to execute user online expire clear task===============
  6. 2019-08-27 13:52:23,816 [atomic-task-asyn-1 - uLVPoWmpHm4Q] DEBUG c.i.u.u.d.U.deleteByExample - ==> Preparing: delete from SYS_USER_ONLINE_INFO WHERE ( EXPIRE_TIME <= ? )
  7. 2019-08-27 13:52:23,826 [atomic-task-asyn-1 - uLVPoWmpHm4Q] DEBUG c.i.u.u.d.U.deleteByExample - ==> Parameters: 2019-08-27 13:52:23.728(Timestamp)
  8. 2019-08-27 13:52:23,828 [atomic-task-asyn-1 - uLVPoWmpHm4Q] DEBUG c.i.u.u.d.U.deleteByExample - <== Updates: 0
  9. 2019-08-27 13:52:23,829 [atomic-task-asyn-1 - uLVPoWmpHm4Q] INFO c.i.u.u.t.UserOnlineTask - end for execute user online expire clear task , delete 0 record===============
  10. 2019-08-27 13:52:23,830 [atomic-task-asyn-1 - uLVPoWmpHm4Q] DEBUG c.i.b.a.d.AutoTaskDAO - =============the update sql:UPDATE SYS_AUTO_TASK SET TASK_NO=:taskNo,TASK_TYPE=:taskType,NEXT_EXEC_TIME=:nextExecTime,LAST_EXECED_TIME=:lastExecedTime,EXEC_MSG=:execMsg,TASK_STATE=:taskState,UPDATE_TIME=:updateTime WHERE TASK_NO=:taskNo AND TASK_TYPE=:taskType
  11. 2019-08-27 13:52:23,830 [atomic-task-asyn-1 - uLVPoWmpHm4Q] DEBUG c.i.b.a.d.AutoTaskDAO - ==========updateBykey paramMap :{nextExecTime=Tue Aug 27 13:52:28 CST 2019, serialVersionUID=1, taskType=CLEAR_ONLINE, taskState=COMPLETE, lastExecedTime=Tue Aug 27 13:52:23 CST 2019, taskNo=20190827135323, execMsg=, updateTime=Tue Aug 27 13:52:23 CST 2019}
  12. 2019-08-27 13:52:23,833 [atomic-task-asyn-1 - uLVPoWmpHm4Q] INFO c.i.b.a.s.AutoTaskService - executed task taskType[CLEA
  • 先使用命令行grep 订单ID xxx.log在log日志中查询某个订单的处理日志,找到其中一个的traceNo
  • 在使用 grep 'uLVPoWmpHm4Q' xxx.log -col 就能够看到某一个线程的所有操作

多线程调用

如果出现线程池,或者MQ的请求,我们需要手动设置类似的trace操作

TraceNoUtils.newTraceNo();
LoggerFactory.getLogger(this.getClass()).info("test");
Thread t = new Thread(new InheritTraceNoRunableWrapper(new Runnable() {

	@Override
	public void run() {
		LoggerFactory.getLogger(this.getClass()).info("thread");
		LoggerFactory.getLogger(this.getClass()).info("thread", new Exception("exception"));
	}
}));
t.start();
t.join();
LoggerFactory.getLogger(this.getClass()).info("abb\nnewLine");
TraceNoUtils.clearTraceNo();

最终输出

  1. 2019-08-27 14:15:15,340 [main - lw8IjvWkXYDb] INFO c.i.b.l.t.TraceNoUtilsTest - test
  2. 2019-08-27 14:15:15,343 [Thread-0 - lw8IjvWkXYDb-iPkVbt] INFO c.i.b.l.t.TraceNoUtilsTest$1 - thread
  3. 2019-08-27 14:15:15,347 [Thread-0 - lw8IjvWkXYDb-iPkVbt] INFO c.i.b.l.t.TraceNoUtilsTest$1 - thread
  4. [lw8IjvWkXYDb-iPkVbt] java.lang.Exception: exception
  5. [lw8IjvWkXYDb-iPkVbt] at com.istock.base.logtrace.test.TraceNoUtilsTest$1.run(TraceNoUtilsTest.java:20) [test-classes/:na]
  6. [lw8IjvWkXYDb-iPkVbt] at com.istock.base.logtrace.wrapper.InheritTraceNoRunableWrapper.run(InheritTraceNoRunableWrapper.java:27) [classes/:na]
  7. [lw8IjvWkXYDb-iPkVbt] at java.lang.Thread.run(Thread.java:745) [na:1.8.0_111] 8.2019-08-27 14:15:15,347 [main - lw8IjvWkXYDb] INFO c.i.b.l.t.TraceNoUtilsTest - abb

本方法适用于线程池或者MQ的调用

  1. 在方法启动前,使用TraceNoUtils.newTraceNo()
  2. 在创建Thread的时候使用InheritTraceNoRunableWrapper包装
  3. 在方法调用后,需要TraceNoUtils.clearTraceNo()

特别是在没有使用ThreadFactory构建线程名称的时候,原本的困难的排错,更加能显示logTrace的优势.

在没有使用ETL的情况下,logTrace是最简单,侵入最小,使用最方便的日志排查方式,到目前为止,没有之一.

就算是用了ETL,logTrace本身也和ETL不冲突.主要是因为侵入小,成本低.