logback MDC线上问题快速定位神器

Logback 快速定位用户在一次请求中的所有日志

问题描述

最近经常做线上问题的排查，而排查问题用得最多的方式是查看日志，但是在现有系统中，各种无关日志穿行其中，导致我没办法快速的找出用户在一次请求中所有的日志。

问题分析

我们没办法快速定位用户在一次请求中对应的所有日志，或者说是定位某个用户操作的所有日志，那是因为我们在输出的日志的时候没把请求的唯一标示或者说是用户身份标示输出到我们的日志中，导致我们没办法根据一个请求或者用户身份标示来做日志的过滤。所以我们在记录日志的是后把请求的唯一标示（requestId）或者身份标示（userId） 记录到日志中这个问题就可以得到很好的解决了。

解决方案

在每次请求的时候，或者是方法执行，或者是任务触发，为每一个请求或方法的执行打上统一的标识，这样就可以根据唯一请求标示获取全部的日志信息

我们使用Logback的MDC机制，日志模板中加入requestId格式。在日志输出格式中指定输出requestId。如：

[%d{yyyy-MM-dd HH:mm:ss.SSS}] [%X{sessionId}] [%thread] %-5level %logger{36} - %msg%n

这种方式工作量小，代码侵入小，易扩展，但是可控粒度低。

方案说明

这种方案很简单，也很容易实现，就是在输出日志的时候多输出一个参数，如：

[2018-11-23 13:51:38.403] [5216149e7fae45019a666775f2fe89a7] [http-bio-8080-exec-6] INFO  com.logback.dao.impl.LogBackDaoImpl - 保存用户成功---LogBackDao

执行步骤

我们在这里使用一个servlet模拟一个用户保存的过程，使用MVC的设计模式分层，view,service.dao
直接上代码

服务端

dao部分

public class LogBackDaoImpl implements LogBackDao {
	
	Logger logger = LoggerFactory.getLogger(LogBackDaoImpl.class);

	public void saveUser(User user) {
		logger.info("保存用户成功---LogBackDao");
	}
}

service 部分

public class LogbackServiceImpl implements LogbackService{
	
	private LogBackDao logBackDao;

	Logger logger = LoggerFactory.getLogger(LogbackServiceImpl.class);
	
	public void savaUser(User user) {
		logBackDao.saveUser(user);
		logger.info("调用LogBackDao保存用户成功");
	}

	public LogBackDao getLogBackDao() {
		return logBackDao;
	}

	public void setLogBackDao(LogBackDao logBackDao) {
		this.logBackDao = logBackDao;
	}
	
}

controller 部分

/**
 * Servlet implementation class LogBackController
 */
public class LogBackController extends HttpServlet {
	private static final long serialVersionUID = 1L;
	
	Logger logger = LoggerFactory.getLogger(LogBackController.class);
	
	private final static String SESSION_KEY = "sessionId";

    /**
     * Default constructor. 
     */
    public LogBackController() {
        // TODO Auto-generated constructor stubW
    }

	/**
	 * @see HttpServlet#doGet(HttpServletRequest request, HttpServletResponse response)
	 */
	protected void doGet(HttpServletRequest request, HttpServletResponse response) throws ServletException, IOException {
		
		// 设置SessionId
        String token = UUID.randomUUID().toString().replace("-", "");
        MDC.put(SESSION_KEY, token);
        
		logger.info("请求到来");
		
		LogBackDao logBackDao = new LogBackDaoImpl();
		LogbackServiceImpl logbackService = new LogbackServiceImpl();
		logbackService.setLogBackDao(logBackDao);
		
		String username = request.getParameter("username");
		String password = request.getParameter("password");
		User user = new User();
		user.setPassword(password);
		user.setUsername(username);
		logbackService.savaUser(user);
		
		logger.info("请求请求结束");
		
		MDC.remove(SESSION_KEY);
	}

	/**
	 * @see HttpServlet#doPost(HttpServletRequest request, HttpServletResponse response)
	 */
	protected void doPost(HttpServletRequest request, HttpServletResponse response) throws ServletException, IOException {
		// TODO Auto-generated method stub
		doGet(request, response);
	}

}

logback.xml

<configuration>
	<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">  
		<encoder>  
			<pattern>[%d{yyyy-MM-dd HH:mm:ss.SSS}] [%X{sessionId}] [%thread] %-5level %logger{36} - %msg%n</pattern>  
		</encoder>  
	</appender> 

	<root level="DEBUG">
		<appender-ref ref="STDOUT" />
	</root>
</configuration>

服务端部分到此完成

客户端

使用线程调用服务100次查看服务端结果

RequestThread 代码

package com.logback;

import java.io.ByteArrayOutputStream;
import java.io.IOException;
import java.io.InputStream;
import java.net.HttpURLConnection;
import java.net.URL;

public class RequestThread extends Thread{

	@Override
	public void run() {
		request();
	}
	
	
	public static void request() {
		String path = "http://localhost:8080/logback/LogBackController?username=aaa&password=bbb";
		try {
			URL url = new URL(path.trim());
			// 打开连接
			HttpURLConnection urlConnection = (HttpURLConnection) url.openConnection();

			if (200 == urlConnection.getResponseCode()) {
				// 得到输入流
				InputStream is = urlConnection.getInputStream();
				ByteArrayOutputStream baos = new ByteArrayOutputStream();
				byte[] buffer = new byte[1024];
				int len = 0;
				while (-1 != (len = is.read(buffer))) {
					baos.write(buffer, 0, len);
					baos.flush();
				}
				System.out.println(baos.toString("utf-8"));
			}
		} catch (IOException e) {
			e.printStackTrace();
		}
	}
}

LogbackTest

public class LogbackTest {

	public static void main(String[] args) {
		
		ExecutorService threadPool = Executors.newFixedThreadPool(5);
		for (int i = 0; i < 100; i++) {
			RequestThread thread = new RequestThread();
			threadPool.execute(thread);
		}
	}
}

只要执行LogbackTest 的main方法就可以得到日志，日志如下：

[2018-11-23 13:51:38.332] [786a5879d7414c09b3208b5efa86f858] [http-bio-8080-exec-9] INFO  c.l.controller.LogBackController - 请求到来
[2018-11-23 13:51:38.332] [ea0757a9c56b4de2a25b5fd92d464741] [http-bio-8080-exec-6] INFO  c.l.controller.LogBackController - 请求到来
[2018-11-23 13:51:38.332] [117903b518c248739cf0e974a30b0ea2] [http-bio-8080-exec-5] INFO  c.l.controller.LogBackController - 请求到来
[2018-11-23 13:51:38.332] [18d3fd3681264e38803cd1d03bec1dd9] [http-bio-8080-exec-7] INFO  c.l.controller.LogBackController - 请求到来
[2018-11-23 13:51:38.332] [d54718d4e14a4b9aba10ce2ac589e2a0] [http-bio-8080-exec-8] INFO  c.l.controller.LogBackController - 请求到来
[2018-11-23 13:51:38.340] [d54718d4e14a4b9aba10ce2ac589e2a0] [http-bio-8080-exec-8] INFO  com.logback.dao.impl.LogBackDaoImpl - 保存用户成功---LogBackDao
[2018-11-23 13:51:38.340] [d54718d4e14a4b9aba10ce2ac589e2a0] [http-bio-8080-exec-8] INFO  c.l.service.impl.LogbackServiceImpl - 调用LogBackDao保存用户成功
[2018-11-23 13:51:38.340] [786a5879d7414c09b3208b5efa86f858] [http-bio-8080-exec-9] INFO  com.logback.dao.impl.LogBackDaoImpl - 保存用户成功---LogBackDao
[2018-11-23 13:51:38.340] [d54718d4e14a4b9aba10ce2ac589e2a0] [http-bio-8080-exec-8] INFO  c.l.controller.LogBackController - 请求请求结束
[2018-11-23 13:51:38.340] [ea0757a9c56b4de2a25b5fd92d464741] [http-bio-8080-exec-6] INFO  com.logback.dao.impl.LogBackDaoImpl - 保存用户成功---LogBackDao
[2018-11-23 13:51:38.340] [ea0757a9c56b4de2a25b5fd92d464741] [http-bio-8080-exec-6] INFO  c.l.service.impl.LogbackServiceImpl - 调用LogBackDao保存用户成功
[2018-11-23 13:51:38.340] [ea0757a9c56b4de2a25b5fd92d464741] [http-bio-8080-exec-6] INFO  c.l.controller.LogBackController - 请求请求结束
[2018-11-23 13:51:38.340] [18d3fd3681264e38803cd1d03bec1dd9] [http-bio-8080-exec-7] INFO  com.logback.dao.impl.LogBackDaoImpl - 保存用户成功---LogBackDao
[2018-11-23 13:51:38.341] [18d3fd3681264e38803cd1d03bec1dd9] [http-bio-8080-exec-7] INFO  c.l.service.impl.LogbackServiceImpl - 调用LogBackDao保存用户成功
[2018-11-23 13:51:38.341] [18d3fd3681264e38803cd1d03bec1dd9] [http-bio-8080-exec-7] INFO  c.l.controller.LogBackController - 请求请求结束
[2018-11-23 13:51:38.340] [117903b518c248739cf0e974a30b0ea2] [http-bio-8080-exec-5] INFO  com.logback.dao.impl.LogBackDaoImpl - 保存用户成功---LogBackDao
[2018-11-23 13:51:38.340] [786a5879d7414c09b3208b5efa86f858] [http-bio-8080-exec-9] INFO  c.l.service.impl.LogbackServiceImpl - 调用LogBackDao保存用户成功
[2018-11-23 13:51:38.342] [117903b518c248739cf0e974a30b0ea2] [http-bio-8080-exec-5] INFO  c.l.service.impl.LogbackServiceImpl - 调用LogBackDao保存用户成功