微服务应用日志处理与组件封装

微服务应用日志组件定制

随着微服务等设计理念在系统中的应用，业务的调用链越来越复杂，日志信息越来越大，从快速增长的日志数据流中提取出所需的信息，并将其与其他相关联的事件进行关联，将变得越加困难。ELK+KafKa作为微服务应用日志中心解决方案是业界常规办法，前提是应用日志输出的规范化，日志组件就是为了完成这一目标。

微服务应用日志格式规划

经过公司技术人员充分讨论和分析，确认了应用日志输出格式如下：

|时间|日志级别|线程名|代码发生行|同步调用ID|客户系统节点|服务系统节点|客户系统名称|服务系统名称|日志类型|全局流水号|定制化字段^日志信息|

时间：记录日志产生时间;
日志级别：FATAL、ERROR、WARN、INFO、DEBUG;
线程名：执行操作线程名称;
代码发生行：日志事件发生在代码中位置;
同步调用ID：用于同步调用链分析、可以关联ZipKin、Pinpoint等工具关联排查问题;
客户系统节点：表示服务-客户端系统节点的标识，可以为IP或者DockerID;
服务系统节点：表示服务-服务端系统节点的标识，可以为IP或者DockerID;
客户系统名称：表示服务-客户端系统的标识，可以为系统简称和全称;
服务系统名称：表示服务-服务端系统的标识，可以为系统简称和全称;
全局流水号：贯穿一次业务流程的全局流水号;
日志类型：枚举，REQ-接口请求报文，RESP-接口响应报文，BIZ-通用日志;
INFO:定制化字段(格式采用关键字段=值，关键字段2=值) ^ 业务信息(记录详细日志信息)。

举个栗子：

|2018-03-28 14:26:21.001|INFO|demo-service-woker:share-d-3[share]-thread-1|com.xxxx.xxx.service.interceptor.ParamCheckInterceptor:59:doInvoke|4507080825331412517041832|127.0.0.1:50344|127.0.0.1:20015|demo-a|demo-b|20170428142618325183APP|BIZ|phoneNumber=185****1234, woAccountId=110000008592138^参数及权限校验拦截，验证通过.|

日志组件实现方案

Java技术平台日志输出组件主要有java.util.logging、log4j、log4j2、logback、slf4j。我司目前使用的log4j2+slf4j组合作为应用日志输出组件，为了实现上述日志格式输出，主要有两种方式在组件上实现封装。应用采用SpringBoot+Restful作为主框架

Log4J的MDC方案

MDC[http://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/MDC.html]是为每个线程建立一个独立的存储空间，开发人员可以根据需要把信息存入其中。MDC使用Map机制来存储信息，信息以key/value对的形式存储在Map中。
使用Servlet Filter或者AOP在服务接收到请求时，获取需要的值填充MDC。在log4j2的配置中就可以使用%X{key}打印MDC中的内容，从而识别出同一次请求中的log。

Log4j2.X版本

MdcLogfilter类

public class MdcLogfilter implements Filter {

    public static final String TRACE_ID = "traceId";

    public static final String CLIENT_ADDR = "clientAddr";

    public static final String SERVER_ADDR = "serverAddr";

    public static final String CLIENT_SYS_NAME = "clientSysName";

    public static final String SERVER_SYS_NAME = "serverSysName";

    public static final String TRANS_ID = "transId";

    public static final String LOG_TYPE = LogTypeEnum.BIZ.getKey();

    private String systemName;

    public MdcLogfilter( String systemName ) {
        this.systemName = systemName;
    }

    @Override
    public void init( FilterConfig filterConfig ) throws ServletException {
    }

    @Override
    public void doFilter( ServletRequest request, ServletResponse response, FilterChain chain ) throws IOException, ServletException {
        try {
            insertIntoMDC(request);
            chain.doFilter(request, response);
        } finally {
            ThreadContext.clearAll();
        }
    }

    @Override
    public void destroy() {
    }

    protected void insertIntoMDC( ServletRequest request ) {
        HttpServletRequest httpRequest = (HttpServletRequest) request;
        String traceId = httpRequest.getHeader(TRACE_ID);
        String clientAddr = httpRequest.getRemoteAddr();
        String serverAddr = getSreverAddr();
        String clientSysName = httpRequest.getHeader(CLIENT_SYS_NAME);
        String serverSysName = systemName;
        String transId = (String) httpRequest.getAttribute(TRANS_ID);
        ThreadContext.put(TRACE_ID, traceId);
        ThreadContext.put(CLIENT_ADDR, clientAddr);
        ThreadContext.put(SERVER_ADDR, serverAddr);
        ThreadContext.put(CLIENT_SYS_NAME, clientSysName);
        ThreadContext.put(SERVER_SYS_NAME, serverSysName);
        ThreadContext.put(TRANS_ID, transId);
        ThreadContext.put(LOG_TYPE, LogTypeEnum.REQ.getKey());
    }

    private String getServerAddr() {
        return null;
    }

}

MDCLogAspect类

@Aspect
public class MDCLogAspect {

    private static final Logger LOGGER = LoggerFactory.getLogger(EpayLogAspect.class);

    private static long STIME = LogUtil.getNowTimeInMillis();

    private static String REQUESTURL = "url";

    @Pointcut("execution(public * com.demo..*.*.controller.*.*(..))")
    public void log() {
    }

    @Before("log()")
    public void deBefore( JoinPoint joinPoint ) throws Throwable {
        STIME = LogUtil.getNowTimeInMillis();
        ServletRequestAttributes attributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();
        HttpServletRequest request = attributes.getRequest();
        Map<String, String[]> params = request.getParameterMap();
        String queryString = "";
        for (String key : params.keySet()) {
            String[] values = params.get(key);
            for (int i = 0; i < values.length; i++) {
                String value = values[i];
                queryString += key + "=" + value + "&";
            }
        }
        
        if (!StringUtils.isEmpty(queryString)){
            queryString = queryString.substring(0, queryString.length() - 1);
        }
        REQUESTURL = request.getRequestURL().toString();

        LOGGER.info("url：{}，req：{}", REQUESTURL, queryString);
        MDC.put(LogPreKeyConstants.LOGTYPE, LogTypeEnum.BIZ.getKey());
    }

    @AfterReturning(returning = "ret", pointcut = "log()")
    public void doAfterReturning( Object ret ) throws Throwable {
        MDC.put(LogPreKeyConstants.LOGTYPE, LogTypeEnum.RESP.getKey());
        LOGGER.info("url：{}，resp：{}", REQUESTURL, ret);
        MDC.remove(LogPreKeyConstants.LOGTYPE);
        MDC.put(LogPreKeyConstants.LOGTYPE, LogTypeEnum.BIZ.getKey());
    }

    //后置异常通知
    @AfterThrowing("log()")
    public void throwss( JoinPoint jp ) {
        String costtime = LogUtil.getNowTimeInMillis() - STIME + "ms";
        LOGGER.info("url：{}，executetime：{}", REQUESTURL, costtime);
    }

    //后置最终通知,final增强，不管是抛出异常或者正常退出都会执行
    @After("log()")
    public void after( JoinPoint jp ) {
        String costtime = LogUtil.getNowTimeInMillis() - STIME + "ms";
        LOGGER.info("url：{}，executetime：{}", REQUESTURL, costtime);
    }
}

Log4j1.X版本

log4j1.x版本，ThreadContext类换成MDC即可

log4j配置使用MDC

在log4j配置中，使用mdc：（log4j 1.x 与 2.x中都可以使用此配置）

<PatternLayout pattern="|%d{yyyy-MM-dd HH:mm:ss.SSS}|%5p|%5t|%4c:%L|%X{traceid}|%X{clientaddr}|%X{serveraddr}|%X{cientsysname}|%X{serversysname}|%X{transid}|%X{logType}|%m|%n" />

Springboot使用

实现定制化log-start,应用依赖即可。

Log4J的适配器封装方案

使用适配器模式封装log4j接口，使用AOP在服务接收到请求时，获取需要的值填充本地线程副本中，打印日志时候拼接输出到日志。

Log4j2.X/Log4j1.X版本

LogContextHolder

public class AdapterLogContextHolder {

    private static final ThreadLocal<AdapterLogContext> LOG_CONTEXT = new ThreadLocal<>();

    private static AdapterLogContextHolder context = new AdapterLogContextHolder();

    private AdapterLogContextHolder() {
    }

    public static AdapterLogContextHolder getInstance() {
        return context;
    }

    public AdapterLogContext getLogContext() {
        AdapterLogContext context = LOG_CONTEXT.get();

        if (context == null) {
            context = new AdapterLogContext();
            LOG_CONTEXT.set(context);
        }
        return context;
    }

    public void setLogContext( AdapterLogContext context ) {
        LOG_CONTEXT.set(context);
    }

    public void removeLogContext() {
        LOG_CONTEXT.remove();
    }

    public String getTraceID() {
        return getLogContext().getTraceID();
    }

    public void setTraceID( String id ) {
        getLogContext().setTraceID(id);
    }
}

AdapterLogContext

public class AdapterLogContext implements Serializable, Cloneable {

    private static final long serialVersionUID = 6126191683350551062L;

    private String traceID = "traceID";

    private long callStartTimes;

    private String transID = "transId";

    private String clientAddr = "clientAddr";

    private String serverAddr = "serverAddr";

    private String clientSysName = "clientSysName";

    private String serverSysName = "serverSysName";

    @Override
    public Object clone() throws CloneNotSupportedException {
        return super.clone();
    }
    //get、set .....
}

LoggerAdapter

public class LoggerAdapter {

    final static String FQCN = LoggerAdapter.class.getName();

    private static LoggerAdapter loggerAdapter;

    private static volatile HashMap<String, LoggerAdapter> loggerxMap = null;

    protected Logger logger = null;

    private LoggerAdapter( Logger logger ) {
        this.logger = logger;
    }

    public static LoggerAdapter getLogger( Class<?> classObject ) {

        if (null == classObject) {
            throw new IllegalArgumentException();
        }

        if (loggerxMap == null) {
            synchronized (Loggerx.class) {
                if (loggerxMap == null) {
                    loggerxMap = new HashMap<>();
                    return getLoggerAdapter(classObject);
                }
            }
        }

        LoggerAdapter loggerAdapter = loggerxMap.get(classObject.getSimpleName());
        if (loggerAdapter == null) {
            return getLoggerAdapter(classObject);
        } else {
            return loggerAdapter;
        }
    }

    private static LoggerAdapter getLoggerAdapter( Class<?> classObject ) {
        Logger logger = LogManager.getLogger(classObject);
        if (logger == null) {
            return null;
        }

        LoggerAdapter loggerAdapter = new LoggerAdapter(logger);
        loggerxMap.put(classObject.getSimpleName(), loggerAdapter);

        return loggerAdapter;
    }

    public void info( LogType logType, Object message ) {
        String msgFormatted = msgFormat(logType, message);
        logger.log(FQCN, Level.INFO, msgFormatted, null);
    }

    public void info( LogType logType, Map<String, String> custMsg, Object message ) {
        String msgFormatted = msgFormat(logType, custMsg, message);
        logger.log(FQCN, Level.INFO, msgFormatted, null);
    }

    public void error( LogType logType, Object message ) {
        String msgFormatted = msgFormat(logType, message);
        logger.log(FQCN, Level.ERROR, msgFormatted, null);
    }

    public void error( LogType logType, Map<String, String> custMsg, Object message ) {
        String msgFormatted = msgFormat(logType, custMsg, message);
        logger.log(FQCN, Level.ERROR, msgFormatted, null);
    }

    public void error( LogType logType, Object message, Throwable t ) {
        String msgFormatted = msgFormat(logType, message);
        logger.log(FQCN, Level.ERROR, msgFormatted, t);
    }

    public void error( LogType logType, Map<String, String> custMsg, Object message, Throwable t ) {
        String msgFormatted = msgFormat(logType, custMsg, message);
        logger.log(FQCN, Level.ERROR, msgFormatted, t);
    }

    public void warn( LogType logType, Object message ) {
        String msgFormatted = msgFormat(logType, message);
        logger.log(FQCN, Level.WARN, msgFormatted, null);
    }

    public void warn( LogType logType, Map<String, String> custMsg, Object message ) {
        String msgFormatted = msgFormat(logType, custMsg, message);
        logger.log(FQCN, Level.WARN, msgFormatted, null);
    }

    public void debug( LogType logType, Object message ) {
        String msgFormatted = msgFormat(logType, message);
        logger.log(FQCN, Level.DEBUG, msgFormatted, null);
    }

    protected String msgFormat( LogType logType, Object message ) {
        StringBuilder sb = new StringBuilder();
        AdapterLogContext logContext = AdapterLogContextHolder.getInstance().getLogContext();
        sb.append(logContext.getTraceID());
        sb.append("|").append(logContext.getClientAddr());
        sb.append("|").append(logContext.getServerAddr());
        sb.append("|").append(logContext.getClientSysName());
        sb.append("|").append(logContext.getServerAddr());
        sb.append("|").append(logContext.getTransID());
        sb.append("|").append(logType);
        sb.append("|").append("custmsg=null");
        sb.append(message != null ? "^" + message.toString().replaceAll("\r|\n", "").replaceAll("\\|", "#") + "|" : "");
        return sb.toString();
    }

    protected String msgFormat( LogType logType, Map<String, String> custMsgMap, Object message ) {
        if (custMsgMap == null || custMsgMap.isEmpty()) {
            return msgFormat(logType, message);
        } else {
            StringBuilder sb = new StringBuilder();
            AdapterLogContext logContext = AdapterLogContextHolder.getInstance().getLogContext();
            sb.append("|").append(logContext.getClientAddr());
            sb.append("|").append(logContext.getServerAddr());
            sb.append("|").append(logContext.getClientSysName());
            sb.append("|").append(logContext.getServerAddr());
            sb.append("|").append(logContext.getTransID());
            sb.append("|").append(logType);
            sb.append("|");
            for (Map.Entry<String, String> entry : custMsgMap.entrySet()) {
                sb.append(entry.getKey() + "=" + entry.getValue() + ",");
            }
            sb.deleteCharAt(sb.length() - 1);
            sb.append(message != null ? "^" + message.toString().replaceAll("\r|\n", "") + "|" : "");
            return sb.toString();
        }
    }
}

AOP切片类LoggerAdapter

public class ClientContextBeforeAdvice implements MethodBeforeAdvice {

    @Override
    public void before(Method arg0, Object[] arg1, Object arg2) throws Throwable {
        try {
            if (arg1.length == 0 || !(arg1[0] instanceof BaseRequest)) {
                return;
            }

            AdapterLogContext logContext = AdapterLogContextHolder.getInstance().getLogContext()

            //获取logContext各个属性值
            BaseRequest request = (BaseRequest) arg1[0];
            request.setLogContext(logContext);
        } catch (Exception e) {
            LOGGER.error(LogType.EX, "", e);
            throw e;
        }
    }
}

//其他AOP切片

log4j配置使用适配器模式

在log4j配置中，log4j 1.x 与 2.x中都可以使用正常配置

Springboot使用

实现定制化log-start,应用依赖即可。

MDC方式与Adapter方式对比

两种对比，MDC优点在于不改变开发人员使用log4j方法，引入不需要更改业务代码，Adapter优势在于使用AOP和ThreadLocal方式更方便定制化。我司目前使用MDC方案.

最后编辑于：2018.05.11 19:57:45

人面猴
序言：七十年代末，一起剥皮案震惊了整个滨河市，随后出现的几起案子，更是在滨河造成了极大的恐慌，老刑警刘岩，带你破解...
沈念sama阅读 202,723评论 5赞 476
死咒
序言：滨河连续发生了三起死亡事件，死亡现场离奇诡异，居然都是意外死亡，警方通过查阅死者的电脑和手机，发现死者居然都...
沈念sama阅读 85,080评论 2赞 379
救了他两次的神仙让他今天三更去死
文/潘晓璐我一进店门，熙熙楼的掌柜王于贵愁眉苦脸地迎上来，“玉大人，你说我怎么就摊上这事。” “怎么了？”我有些...
开封第一讲书人阅读 149,604评论 0赞 335
道士缉凶录：失踪的卖姜人
文/不坏的土叔我叫张陵，是天一观的道长。经常有香客问我，道长，这世上最难降的妖魔是什么？我笑而不...
开封第一讲书人阅读 54,440评论 1赞 273
港岛之恋（遗憾婚礼）
正文为了忘掉前任，我火速办了婚礼，结果婚礼上，老公的妹妹穿的比我还像新娘。我一直安慰自己，他们只是感情好，可当我...
茶点故事阅读 63,431评论 5赞 364
恶毒庶女顶嫁案：这布局不是一般人想出来的
文/花漫我一把揭开白布。她就那样静静地躺着，像睡着了一般。火红的嫁衣衬着肌肤如雪。梳的纹丝不乱的头发上，一...
开封第一讲书人阅读 48,499评论 1赞 281
城市分裂传说
那天，我揣着相机与录音，去河边找鬼。笑死，一个胖子当着我的面吹牛，可吹牛的内容都是我干的。我是一名探鬼主播，决...
沈念sama阅读 37,893评论 3赞 395
双鸳鸯连环套：你想象不到人心有多黑
文/苍兰香墨我猛地睁开眼，长吁一口气：“原来是场噩梦啊……” “哼！你这毒妇竟也来了？” 一声冷哼从身侧响起，我...
开封第一讲书人阅读 36,541评论 0赞 256
万荣杀人案实录
序言：老挝万荣一对情侣失踪，失踪者是张志新（化名）和其女友刘颖，没想到半个月后，有当地人在树林里发现了一具尸体，经...
沈念sama阅读 40,751评论 1赞 296
护林员之死
正文独居荒郊野岭守林人离奇死亡，尸身上长有42处带血的脓包…… 初始之章·张勋以下内容为张勋视角年9月15日...
茶点故事阅读 35,547评论 2赞 319
白月光启示录
正文我和宋清朗相恋三年，在试婚纱的时候发现自己被绿了。大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
茶点故事阅读 37,619评论 1赞 329
活死人
序言：一个原本活蹦乱跳的男人离奇死亡，死状恐怖，灵堂内的尸体忽然破棺而出，到底是诈尸还是另有隐情，我是刑警宁泽，带...
沈念sama阅读 33,320评论 4赞 318
日本核电站爆炸内幕
正文年R本政府宣布，位于F岛的核电站，受9级特大地震影响，放射性物质发生泄漏。R本人自食恶果不足惜，却给世界环境...
茶点故事阅读 38,890评论 3赞 307
男人毒药：我在死后第九天来索命
文/蒙蒙一、第九天我趴在偏房一处隐蔽的房顶上张望。院中可真热闹，春花似锦、人声如沸。这庄子的主人今日做“春日...
开封第一讲书人阅读 29,896评论 0赞 19
一桩弑父案，背后竟有这般阴谋
文/苍兰香墨我抬头看了看天上的太阳。三九已至，却和暖如春，着一层夹袄步出监牢的瞬间，已是汗流浃背。一阵脚步声响...
开封第一讲书人阅读 31,137评论 1赞 259
情欲美人皮
我被黑心中介骗来泰国打工，没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留，地道东北人。一个月前我还...
沈念sama阅读 42,796评论 2赞 349
代替公主和亲
正文我出身青楼，却偏偏与公主长得像，于是被迫代替她去往敌国和亲。传闻我的和亲对象是个残疾皇子，可洞房花烛夜当晚...
茶点故事阅读 42,335评论 2赞 342

微服务应用日志处理与组件封装

微服务应用日志组件定制

微服务应用日志格式规划

日志组件实现方案

Log4J的MDC方案

Log4j2.X版本

MdcLogfilter类

MDCLogAspect类

Log4j1.X版本

log4j配置使用MDC

Springboot使用

Log4J的适配器封装方案

Log4j2.X/Log4j1.X版本

LogContextHolder

AdapterLogContext

LoggerAdapter

AOP切片类LoggerAdapter

log4j配置使用适配器模式

Springboot使用

MDC方式与Adapter方式对比

推荐阅读更多精彩内容