MelonBlog

优雅的打印业务日志

前言

开发和维护业务系统时,经常需要根据日志来排查业务问题,这时候日志会起到非常大的作用,但是打印日志的格式没有一个标准,普遍都是五花八门的,所以我写了一个打印关键日志的工具类,来辅助打印一些关键的业务日志

设计思路

业务逻辑会沿着代码逻辑递进,从外层业务逐步走到内层子业务,一个复杂的业务可能包含许多子业务

image

平常我们打印日志,很难直观体现业务流程,一般都是打印参数或者某个临时变量,排查简单的问题,看变量的值是能够推导出问题的,但是如果碰到业务特别复杂,流程很长的场景,光看变量的值对于排查问题来说帮助就有限。


我想到一个思路,就是在日志里增加业务上下文。

实现方法就是,在Threadlocal里,保存一个业务的栈,栈数据结构可以很好的存储上图的流程,例如通过入栈操作就可以模拟出从某一个业务执行到另外一个业务。无论是嵌套还是组合关系都能够很好的体现出来。

每一个业务里面可能还有很多执行分支,所以业务数据结构里我加了一个标签栈,用来标记业务流程走到了哪个分支。

代码

package com.demo.util;
import com.demo.exception.BaseRuntimeException;
import lombok.Data;
import org.apache.commons.lang3.StringUtils;
import org.slf4j.Logger;
import java.util.Formatter;
import java.util.Stack;
public class Footprint {
    private Logger logger;
    private static final ThreadLocal<Stack<Logic>> logicsThreadLocal = ThreadLocal.withInitial(Stack::new);
    public static Footprint bind(Logger logger) {
        Footprint footprint = new Footprint();
        footprint.logger = logger;
        return footprint;
    }
    public void newLogic(String logic) {
        Footprint.newLogic(this.logger, logic);
    }
    public static void newLogic(Logger logger, String logic) {
        Stack<Logic> logics = logicsThreadLocal.get();
        logics.clear();
        Logic newLogic = new Logic(logic);
        logics.push(newLogic);
        logger.info("{}", newLogic);
    }
    public void pushLogic(String logic) {
        Footprint.pushLogic(this.logger, logic);
    }
    public static void pushLogic(Logger logger, String logic) {
        Stack<Logic> logics = logicsThreadLocal.get();
        if (logics.isEmpty()) {
            newLogic(logger, logic);
            return;
        }
        // 防止logic异常未被释放
        if (logics.size() > 10) {
            logger.warn("logics size is too large, clear all logics");
            logics.clear();
            logics.push(new Logic(logic));
            return;
        }
        Logic currentLogic = logics.peek();
        Logic newLogic = new Logic(currentLogic.logicName + "->" + logic);
        logics.push(newLogic);
        logger.info("{}", newLogic);
    }
    public void popLogic() {
        Footprint.popLogic(this.logger);
    }
    public static void popLogic(Logger logger) {
        Stack<Logic> logics = logicsThreadLocal.get();
        if (logics.isEmpty()) {
            logger.warn("exit logic failed, logics is empty");
            return;
        }
        logics.pop();
    }
    public void popLogic(String logic) {
        Footprint.popLogic(this.logger, logic);
    }
    public static void popLogic(Logger logger, String logic) {
        Stack<Logic> logics = logicsThreadLocal.get();
        if (logics.isEmpty()) {
            logger.warn("exit logic {} failed, logics is empty", logic);
            return;
        }
        if (logics.peek().getLogicName().equals(logic)) {
            logics.pop();
        }
    }
    public void newTag(String... newTags) {
        Footprint.newTag(this.logger, newTags);
    }
    public static void newTag(Logger logger, String... newTags) {
        Logic logic = getCurrentLogic(logger);
        if (logic == null) {
            return;
        }
        Stack<String> tags = logic.getTags();
        if (!tags.isEmpty()) {
            tags.clear();
        }
        for (String tag : newTags) {
            tags.push(tag);
        }
        logger.info("{}", logic);
    }
    public void pushTag(String tag) {
        Footprint.pushTag(this.logger, tag);
    }
    public static void pushTag(Logger logger, String tag) {
        Logic logic = getCurrentLogic(logger);
        if (logic == null) {
            return;
        }
        logic.getTags().push(tag);
        logger.info("{}", logic);
    }
    public void popTag() {
        Footprint.popTag(this.logger);
    }
    public static void popTag(Logger logger) {
        Logic logic = getCurrentLogic(logger);
        if (logic == null) {
            return;
        }
        Stack<String> tags = logic.getTags();
        if (tags.isEmpty()) {
            logger.warn("pop tag failed, tags is empty");
            return;
        }
        tags.pop();
    }
    public void popTag(String tag) {
        Footprint.popTag(this.logger, tag);
    }
    public static void popTag(Logger logger, String tag) {
        Logic logic = getCurrentLogic(logger);
        if (logic == null) {
            return;
        }
        Stack<String> tags = logic.getTags();
        if (tags.peek().equals(tag)) {
            tags.pop();
        }
    }
    public void clearTag() {
        Footprint.clearTag(this.logger);
    }
    public static void clearTag(Logger logger) {
        Logic logic = getCurrentLogic(logger);
        if (logic == null) {
            return;
        }
        Stack<String> tags = logic.getTags();
        tags.clear();
    }
    private static Logic getCurrentLogic(Logger logger) {
        Stack<Logic> logics = logicsThreadLocal.get();
        if (logics.isEmpty()) {
            logger.warn("push tag failed, logics is empty");
            return null;
        }
        return logics.peek();
    }
    public void arg(String name, Object value) {
        Footprint.arg(this.logger, name, value);
    }
    public void args(String varName, Object value, String name2, Object value2) {
        Footprint.args(this.logger, varName, value, name2, value2);
    }
    public void args(String varName, Object value, String name2, Object value2, String name3, Object value3) {
        Footprint.args(this.logger, varName, value, name2, value2, name3, value3);
    }
    public static void arg(Logger logger, String varName, Object value) {
        Stack<Logic> logics = logicsThreadLocal.get();
        if (logics.isEmpty()) {
            logger.debug("{\"{}\": {}}", varName, ParamUtils.toString(value));
        } else {
            Logic logic = logics.peek();
            logger.debug("{} ==> {\"{}\": {}}", logic, varName, ParamUtils.toString(value));
        }
    }
    public static void args(Logger logger, String varName, Object value, String varName2, Object value2) {
        Stack<Logic> logics = logicsThreadLocal.get();
        if (logics.isEmpty()) {
            logger.debug("{\"{}\": {}, \"{}\": {}}", varName, ParamUtils.toString(value), varName2, ParamUtils.toString(value2));
        } else {
            Logic logic = logics.peek();
            logger.debug("{} ==> {\"{}\": {}, \"{}\": {}}",
                         logic,
                         varName,
                         ParamUtils.toString(value),
                         varName2,
                         ParamUtils.toString(value2));
        }
    }
    public static void args(Logger logger, String varName, Object value, String varName2, Object value2, String varName3, Object value3) {
        Stack<Logic> logics = logicsThreadLocal.get();
        if (logics.isEmpty()) {
            logger.debug("{\"{}\": {}, \"{}\": {}, \"{}\": {}}",
                         varName,
                         ParamUtils.toString(value),
                         varName2,
                         ParamUtils.toString(value2),
                         varName3,
                         ParamUtils.toString(value3));
        } else {
            Logic logic = logics.peek();
            logger.debug("{} ==> {\"{}\": {}, \"{}\": {}, \"{}\": {}}",
                         logic,
                         varName,
                         ParamUtils.toString(value),
                         varName2,
                         ParamUtils.toString(value2),
                         varName3,
                         ParamUtils.toString(value3));
        }
    }
    public void info(String format, Object... args) {
        Footprint.info(this.logger, new Formatter().format(format, args).toString());
    }
    public static void info(Logger logger, String format, Object... args) {
        Stack<Logic> logics = logicsThreadLocal.get();
        if (logics.isEmpty()) {
            logger.warn("print failed, logics is empty");
            logger.info(new Formatter().format(format, args).toString());
            return;
        }
        Logic logic = logics.peek();
        logger.info("{} ==> {}", logic, new Formatter().format(format, args));
    }
    public void error(String format, Object... args) {
        Footprint.error(this.logger, format, args);
    }
    public static void error(Logger logger, String format, Object... args) {
        Stack<Logic> logics = logicsThreadLocal.get();
        if (logics.isEmpty()) {
            logger.warn("print failed, logics is empty");
            logger.error(new Formatter().format(format, args).toString());
            return;
        }
        Logic logic = logics.peek();
        logger.error("{} ==> {}", logic, new Formatter().format(format, args));
    }
    public void throwError(String log) throws BaseRuntimeException {
        Footprint.throwError(this.logger, log);
    }
    public static void throwError(Logger logger, String log) throws BaseRuntimeException {
        Stack<Logic> logics = logicsThreadLocal.get();
        if (logics.isEmpty()) {
            logger.error("{}", log);
            throw new BaseRuntimeException(log);
        }
        Logic logic = logics.peek();
        logger.error("{} ==> {}", logic, log);
        logger.error("{} ==> 异常退出", logic);
        logics.pop();
        throw new BaseRuntimeException(log);
    }
    public static void clear(Logger logger) {
        Stack<Logic> logics = logicsThreadLocal.get();
        if (logics.isEmpty()) {
            return;
        }
        Logic logic = logics.peek();
        logger.error("{} ==> 异常退出", logic);
        logicsThreadLocal.get().clear();
    }
    @Data
    public static class Logic {
        private String logicName;
        private Stack<String> tags;
        public Logic(String logicName) {
            this.logicName = logicName;
            this.tags = new Stack<>();
        }
        public String toString() {
            if (tags.isEmpty()) {
                return String.format("[fp][%s]", logicName);
            }
            return String.format("[fp][%s]#[%s]", logicName, StringUtils.join(tags, "|"));
        }
    }
}

测试代码:

package com.demo.util;
import lombok.Data;
import lombok.extern.slf4j.Slf4j;
@Slf4j
public class FootprintTest {
    private final Footprint fp = Footprint.bind(log);
    public void businessA() {
        fp.pushLogic("子业务A");
        fp.newTag("标签1");
        fp.info("白日依山尽");
        fp.pushTag("标签2");
        fp.info("黄河入海流");
        fp.popTag();
        businessB();
        fp.newTag("标签5");
        fp.info("欲穷千里目");
        fp.info("更上一层楼");
        fp.popLogic();
    }
    @Data
    public static class Person {
        private String name;
        private int age;
    }
    public void businessB() {
        fp.pushLogic("子业务B");
        fp.newTag("标签3");
        fp.info("抽刀断水水更流");
        fp.newTag("标签4");
        fp.info("举杯消愁愁更愁");
        Person person = new Person();
        person.age = 18;
        person.name = "李白";
        fp.arg("person", person);
        fp.popLogic();
    }
    public static void main(String[] args) {
        Footprint.newLogic(log, "测试Footprint");
        FootprintTest footprintTest = new FootprintTest();
        footprintTest.businessA();
    }
}

打印内容:

[fp][测试Footprint]
[fp][测试Footprint->子业务A]
[fp][测试Footprint->子业务A]#[标签1]
[fp][测试Footprint->子业务A]#[标签1] ==> 白日依山尽
[fp][测试Footprint->子业务A]#[标签1|标签2]
[fp][测试Footprint->子业务A]#[标签1|标签2] ==> 黄河入海流
[fp][测试Footprint->子业务A->子业务B]
[fp][测试Footprint->子业务A->子业务B]#[标签3]
[fp][测试Footprint->子业务A->子业务B]#[标签3] ==> 抽刀断水水更流
[fp][测试Footprint->子业务A->子业务B]#[标签4]
[fp][测试Footprint->子业务A->子业务B]#[标签4] ==> 举杯消愁愁更愁
[fp][测试Footprint->子业务A->子业务B]#[标签4] ==> {"person": {"age":18,"name":"李白"}}
[fp][测试Footprint->子业务A]#[标签5]
[fp][测试Footprint->子业务A]#[标签5] ==> 欲穷千里目
[fp][测试Footprint->子业务A]#[标签5] ==> 更上一层楼