REST服务中的日志可视化（关键技术实现）

引言

在系统构建完成之后，我们通常会使用REST API对外提供服务，在REST API的处理过程中经常会出现一些异想不到的问题（用户权限不足、参数不全、数据库访问异常等），导致请求失败，很多时候用户并不能理解这些失败是如何造成的，他们更多的是直接找到相应的开发者询问：“我的这个接口失败了，没有拿到数据，帮忙看一下吧”，更为复杂的是当我们询问其他用户的时候，他们却说：“你这个接口是正常的啊”，开发者这时就很郁闷：“我又没对你做特殊处理，怎么别人是好的，偏偏就你的失败”（本人在工作初期，经常遇到此类场景，表示很无奈）。

问题还是要解决，怎么办？找日志呗！打开终端、拿起微盾、输入密码、输入IP，等等！！！我们的REST API是部署在多台服务器上，前面有一台Nginx，“我去，谁知道是哪台服务器处理你的请求的，哦，我们在日志目录下挂载了NFS，每个REST API的日志信息会写入到一个固定的文件夹中”，“你什么时候请求这个接口的”，然后估计一个大概的时间，找到对应的日志文件（日志输出使用Log4j，并按照天进行滚动），“我X，这个接口访问如此频繁，日志全部都混在了一起，怎么找”，“对了，我们有RequestID，每个请求都是唯一的，快找”，“我X，RequestID并不是每行日志都带有的，完了”，日志无法定位，无颜面对用户呀，只好羞愧地对用户说：“我们有测试环境，我给你一个IP，你再访问一次，我看看日志就知道啥原因了”。

多么高大上的回答呀，还是掩饰不住尴尬的内心，唉...

问题终归是要解决的，把程序员（尤其是我）搞的不耐烦了，就要有创新了（自夸一下），另外得知我们的小伙伴们提供ELK服务，REST API日志可视化的想法油然而生。

注：本文仅关注在REST环境下如果自定义日志输出，不涉及ELK部分（其他小伙伴支持，团队的力量）

关键问题

REST API中使用log4j进行日志输出，如何在不影响现有代码的基础上（无须在业务代码中添加任何代码），收集一次请求的日志信息，透明的将日志输出至ELK

解决思路

（1）使用ServletRequestListener对请求过程进行监听，请求过程包含两部分：requestInitialized、requestDestroyed；
（2）每一次请求的初始化、处理、销毁是由一个独立的线程负责完成的（熟悉Java的同学可能立马就会想到ThreadLocal）；
（3）现有业务代码中已经使用log4j作日志输出，为了保证不影响现有代码及以后的开发，唯一的方式，自定义Appender；

通过上述三步，我们可以大致得出这样一个流程：

（1）在ServletRequestListener requestInitialized初始化当前线程的日志对象；
（2）业务代码执行过程中，log4j输出日志时通过我们自定义的Appender，将日志信息保存至当前线程的日志对象中；
（3）在ServletRequestListener requestDestroyed中将当前线程的日志对象中的日志信息输出至目的地（这里是ELK，也可以是其它），然后清空线程对象。

注意：以上全部操作均依赖于一个请求过程的处理全部处于一个线程环境中。

解决方案

（1）定义日志对象

public class DipLog {

    public static class DipLogMessage {

        private String time;

        private String level;

        private String filename;

        private String className;

        private String methodName;

        private String lineNumber;

        private String message;

        public DipLogMessage(String time, String level, String filename,
                String className, String methodName, String lineNumber,
                String message) {
            this.time = time;

            this.level = level;

            this.filename = filename;

            this.className = className;

            this.methodName = methodName;

            this.lineNumber = lineNumber;

            this.message = message;
        }

        public String getTime() {
            return time;
        }

        public String getLevel() {
            return level;
        }

        public String getFilename() {
            return filename;
        }

        public String getClassName() {
            return className;
        }

        public String getMethodName() {
            return methodName;
        }

        public String getLineNumber() {
            return lineNumber;
        }

        public String getMessage() {
            return message;
        }

        @Override
        public String toString() {
            return String.format("%s\t%s\t%s\t%s\t%s\t%s\t%s", time, level,
                    filename, className, methodName, lineNumber, message);
        }

    }

    private Map<String, String> properties = new HashMap<String, String>();

    private List<DipLogMessage> messages = Collections
            .synchronizedList(new ArrayList<DipLog.DipLogMessage>());

    public void addProperty(String key, String value) {
        properties.put(key, value);
    }

    public void addMessage(DipLogMessage message) {
        messages.add(message);
    }

    public Map<String, String> getProperties() {
        return properties;
    }

    public List<DipLogMessage> getMessages() {
        return messages;
    }

}

 

properties中保存一些自定义属性值（log4j本身不支持的），messages中保存通过log4j debug、info、warn、error输出的日志消息（DipLogMessage ）。

（2）通过ThreadLocal保存一个请求处理过程中的日志对象

public class DipLogThreadLocal {

    private static final ThreadLocal<DipLog> DIP_LOG_THREAD_LOCAL = new ThreadLocal<DipLog>();

    public static DipLog get() {
        return DIP_LOG_THREAD_LOCAL.get();
    }

    public static void set(DipLog dipLog) {
        DIP_LOG_THREAD_LOCAL.set(dipLog);
    }

    public static void clear() {
        DIP_LOG_THREAD_LOCAL.set(null);
    }

}

 

（3）扩展Log4j，自定义Appender，将请求处理过程中的日志消息保存至当前线程关联的日志对象中

public class DipLogAppender extends WriterAppender {

    private static final SimpleDateFormat DATETIME_FORMAT = new SimpleDateFormat(
            "yyyy-MM-dd HH:mm:ss,SSS");

    @Override
    public void append(LoggingEvent event) {
        String time = DATETIME_FORMAT.format(new Date(event.getTimeStamp()));

        String level = event.getLevel().toString();

        String filename = event.getLocationInformation().getFileName();

        String className = event.getLocationInformation().getClassName();

        String methodName = event.getLocationInformation().getMethodName();

        String lineNumber = event.getLocationInformation().getLineNumber();

        String message = event.getRenderedMessage();

        DipLogMessage dipLogMessage = new DipLogMessage(time, level, filename,
                className, methodName, lineNumber, message);

        DipLog dipLog = DipLogThreadLocal.get();

        dipLog.addMessage(dipLogMessage);
    }

}

 

(4)创建ServletRequestListener

public class DipLogRequestListener implements ServletRequestListener {

    @Override
    public void requestInitialized(ServletRequestEvent event) {
        DipLog dipLog = new DipLog();

        dipLog.addProperty("requestId",
                String.valueOf(System.currentTimeMillis()));

        dipLog.addProperty("url", ((HttpServletRequest) event
                .getServletRequest()).getRequestURI());

        DipLogThreadLocal.set(dipLog);
    }

    @Override
    public void requestDestroyed(ServletRequestEvent event) {
        DipLog dipLog = DipLogThreadLocal.get();

        Map<String, String> properties = dipLog.getProperties();

        for (Entry<String, String> entry : properties.entrySet()) {
            System.out.println(entry.getKey() + "\t" + entry.getValue());
        }

        List<DipLogMessage> messages = dipLog.getMessages();

        for (DipLogMessage dipLogMessage : messages) {
            System.out.println(dipLogMessage);
        }

        DipLogThreadLocal.clear();
    }

}

 

从黑体部分代码可以看出，我们在日志对象中保存着当前请求的RequestID及URL（可以添加到最后的日志消息输出），通过requestDestroyed完成请求日志消息的具体输出（这里仅仅模拟，直接输出至控制台）。

这里仅仅介绍核心实现，可以在此基础之上根据业务需求扩展出更为复杂的功能。