工程实践：如何规范地打印程序日志？

很久之前，有个朋友问我，如果一个老项目让你接手去进行后续维护，你会先从哪里入手、让自己更快地上手项目？当时我没有特别正面去回答这个朋友的问题，我说：一个老项目是否容易上手，一个非常关键的地方就是这个项目的日志是否打得足够好。因为通常来说，一个老项目相对比较稳定了，后续大概率不会有比较大的变更和改动，那么对于这样的项目，核心就是“维稳”。但是任何人都无法保证项目在线上运行时不会出线上故障，在出现线上问题或者故障时，如何快速止损就是第一要义，而日志在止损过程中就扮演着非常重要的角色。日志打的足够明了清晰，可以帮助开发和运维人员快速定位问题，继而决定采取何种方案进行止损。

今天就让我们一起来聊一聊如何把项目程序日志打“好”。以下是本文大纲目录：

一.为何需要规范地打印程序日志？

二.如何规范地打印程序日志？

若有不正之处请多多谅解，并欢迎批评指正。

请尊重作者劳动成果，转载请标明原文链接：

http://www.dolphin0520.com/archives/2018/11/26/176.html

一.为何需要规范地打印程序日志？

我们平时在写程序代码过程中，一般会把主要精力集中在功能实现上，往往会忽视日志的重要性，然而日志在系统上线后是极其重要的，因为系统上线后，只有通过日志才能了解当前系统的运行状态，在出现线上故障时，日志是否足够清晰明了决定了是否能够快速找到止损方案。我们可以看一下下面这段代码：

public class HttpClient {
    private static final Logger LOG = LoggerFactory.getLogger(HttpClient.class);

    private static int CONNECT_TIMEOUT = 5000;   // unit ms
    private static int READ_TIMEOUT = 10000;     // unit ms
    
    public static String sendPost(String url, String param) {
        OutputStream out = null;
        BufferedReader in = null;
        String result = "";
        try {
            URL realUrl = new URL(url);
            URLConnection conn = realUrl.openConnection();
            conn.setDoInput(true);
            conn.setDoOutput(true);
            conn.setConnectTimeout(CONNECT_TIMEOUT);
            conn.setReadTimeout(READ_TIMEOUT);
            conn.setRequestProperty("charset", "UTF-8");
            out = new PrintWriter(conn.getOutputStream());
            out.print(parm);
            out.flush();
            in = new BufferedReader(new InputStreamReader(conn.getInputStream()));
            String line;
            while ((line = in.readLine()) != null) {
                result += line;
            }
        } catch (Exception ex) {
            LOG.error("post request error!!!");
        } finally {
            try {
                if (out != null) {
                    out.close();
                }
                if (in != null) {
                    in.close();
                }
            } catch (IOException ex) {
                LOG.error("close stream error!!!");
            }
            return result;
        }
    }
}

某一天线上突然大量http请求失败，然后查看日志，发现了大量的“post request error!!!”错误，此时假如看到这样的日志你可能完全不知道究竟是什么原因导致的，还得继续通过一些其他的手段来定位具体原因。

假如打印的错误日志是这样的：

post request error!!!, url:[http://www.123.test.com], param:[name=jack]
java.net.ConnectException: Connection refused
	at java.net.PlainSocketImpl.socketConnect(Native Method)
	at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:339)
	at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:200)
	at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:182)
	at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
	at java.net.Socket.connect(Socket.java:579)

那么便能很快地断定是下游http服务问题导致的，且下游http服务域名为www.123.test.com(Connection refused通常是由于下游服务端口未启动引起的)，可以迅速找相应的人员进行止损，避免在故障定位阶段耗费大量的时间。

上面举的例子只是一个非常小的例子，实际日常开发中可能碰到的线上问题比这个更加复杂和棘手，总结来看，日志的主要作用有以下几点：

1）日志是系统运行的“照妖镜”，通过它能够实时反映系统的运行状态；

如上图所示，系统A中producer不断产生数据放入到data queue中，sender不断从data queue中取数据发送给下游系统B的receiver，那么对于系统A来说，data queue中的待发送数据量便是一个非常关键的指标，它能够从侧面真实反应当前系统的运行状况，如果data queue中的element个数超过容量的90%了，那么标志着此时系统可能运行不正常了，会有队列堵塞的风险；如果data queue中的element个数不到容量的10%，那么标志着此时系统运行比较正常，出现队列堵塞的风险较低。

如果这个指标没有输出到日志中，开发和运维人员是无法确切知道当前系统A的运行状态的(当然也有其他的方式来获取这个指标，比如通过http接口暴露出来也是一种方式之一)。

2）良好的日志便于后期运维和开发人员迅速定位线上问题，加快止损速度，减少系统故障带来的损失；

3）日志还有另外一个作用便是能够无缝与监控系统结合，通过监控系统进行日志采集，拿到系统运行的相关性能指标，有利于分析系统的性能瓶颈、提前规避风险；

举例说明：

假如有一个商城系统，在初期，数据库通过2台服务器提供服务(1台master，1台slave)，此时大部分接口能在秒级内响应用户请求。随着时间的推移，商城系统的用户量逐渐增多，并发查询和写入量都出现了一定的增长，数据库中的数据量也慢慢增多，导致部分sql语句查询越来越慢，突然有一天，数据库的slave机器由于过多的慢查询导致被拖垮，彻底宕机了，导致商城服务不可用。

如果商城系统在日志中记录了每个http请求的耗时情况，通过监控系统配置日志采集，同时配置相应的报警，那么便能提前发现由于业务增长带来的系统性能瓶颈，提前进行系统优化(如机器扩容、sql语句优化、分库分表等)，规避风险。

4）便于统计与业务相关的指标数据，进行相关业务分析和功能优化。

举例说明：

比如一个搜索系统，想统计过去一周不同地域(如南北地域)的搜索使用占比，如果日志中本身打印了每个搜索query请求的ip，则很容易统计，否则需要重新上线加日志才能统计。

因此，大家在日常编写代码过程中要注重日志书写的规范性，让它发挥出它应有的价值，在辅助保障我们服务稳定运行的同时，能够有效提升后期系统维护效率。

二.如何规范地打印程序日志？

接下来，我们从以下几个方面来谈谈如何规范地打印日志。

2.1 日志文件命名

通常来说日志文件的命名可包括以下几个关键信息：

类型标识(logTypeName)
日志级别(logLevel)
日志生成时间(logCreateTime)
日志备份编号(logBackupNum)

类型标识：指此日志文件的功能或者用途，比如一个web服务，记录http请求的日志通常命名为request.log或者access.log，request、access就是类型标识，而java的gc日志通常命名为gc.log，这样看一目了然；而通常用来记录服务的整体运行的日志一般用服务名称(serviceName、appKey)或者机器名(hostName)来命名，如 nginx.log；

日志级别：打印日志的时候直接通过文件来区分级别是一种比较推荐的方式，如果把所有级别的日志打到同一个日志文件中，在定位问题时，还需要去文件中进行查找操作，相对繁琐。日志级别一般包括DEBUG、INFO、WARN、ERROR、FATAL这五个级别，在实际编写代码中，可以采取严格匹配模式或者非严格匹配模式，严格匹配模式即INFO日志文件中只打印INFO日志，ERROR日志文件只打印ERROR日志；非严格匹配模式即INFO日志文件可以打印INFO日志、WARN日志、ERROR日志、FATAL日志，WARN日志文件可以打印WARN日志、ERROR日志、FATAL日志，以此类推。

日志生成时间：即在日志文件名称中附带上日志文件创建的时间，方便在查找日志文件时进行排序；

日志备份编号：当进行日志切割时，如果是以文件大小进行滚动，此时可以在日志文件名称末尾加上编号；

2.2 日志滚动

　　虽然日志中能够保存系统运行时的关键信息，但是由于磁盘空间有限，所以我们不能无限制地保留日志，因此必须有日志滚动策略。日志滚动通常有以下几种模式：

　　第一种：按照时间滚动

　　第二种：按照单个日志文件大小滚动

　　第三种：同时按照时间和单个日志文件大小滚动。

按照时间滚动，即每隔一定的时间建立一个新的日志文件，通常可以按照小时级别滚动或者天级别滚动，具体采取哪种方式取决于系统日志的打印量。如果系统日志比较少，可以采取天级别滚动；而如果系统日常量比较大，则建议采取小时级别滚动。
按照单个日志文件大小滚动，即每当日志文件达到一定大小则建立一个新的日志文件，通常建议单个日志文件大小不要超过500M，日志文件过大的话，对于日志监控或者问题定位排查都可能会造成一定影响。
按照时间和单个日志文件大小滚动，这种模式通常适用于希望保留一定时间的日志，但是又不希望单个日志文件过大的场景。比如logback就提供了这种配置模式，可参考：https://logback.qos.ch/manual/appenders.html#SizeAndTimeBasedFNATP

　　对于日志滚动策略来说，有2个比较关键的参数：最大保留日志数量和最大磁盘占用空间。这2个参数切记一定要设置，如果没有设置，则很有可能会出现把线上机器磁盘打满的情况。

2.3 日志级别

　　日志的级别通常有以下几种：

　　debug/trace、info、warning、error、fatal

　　这几种日志级别的严重程序依次递增：

　　debug/trace：debug和trace级别的日志由于打印内容较多，所以通常情况下不适用于线上生产环境使用，一般使用于前期线下环境调试。即使线上环境要使用，也需要通过开关来控制，只在定位追踪线上问题时才开启；

　　info：info日志一般用来记录系统运行的关键状态、关键业务逻辑或者关键执行节点。但切记一点，info日志绝不可滥用，如果info日志滥用，则和debug/trace日志没有太大区别了。

　　warning：warning日志一般用来记录系统运行时的一些非预期情况，顾名思义，是作为一种警示，提醒开发和运维人员需要关注，但是不用人为介入立刻去处理的。

　　error：error日志一般用来记录系统运行时的一些普通错误，这些错误一旦出现，则表示已经影响了用户的正常访问或者使用，通常意味着需要人为介入处理。但很多时候在生产环境中，也不一定是出现error日志就需要人工立即介入处理的，通常会结合error日志的数量以及持续时间来进行综合判断。

　　fatal：属于系统致命错误，一般出现意味着系统基本等于挂掉了，需要人工立即介入处理。

　　下面举个简单的例子来说明，假如我们有这样一个场景，我们有一个工资计算系统，每隔月1号需要从员工考勤系统获取公司所有员工的考勤数据，然后根据考勤数据来计算上月应发工资，那么需要有一个函数从考勤系统获取员工考勤数据：

public Map<Long, Double> getEmployeeWorkDaysFromAttendance(int year, int month, Set<Long> employeeList) throws BusiessException {
        // 入口关键日志，需要打印关键的参数，因为employeeList可能数量较大，所以次数没有直接打印employeeList列表内容，只打印了size
        logger.info("get employee work days, year:{}, month:{}, employeeList.size:{}", year, month, employeeList.size());

        // 如果需要临时检验员工列表，可以把debug日志开关打开
        if (debugOpen()) {
            logger.debug("employ list content:{}", JSON.toJsonString(employeeList));
        }
        
        int retry = 1;
        while (retry <= MAX_RETRY_TIMES) {
            try {
                Map<Long, Double> employeeWorkDays = employeeAttendanceRPC.getEmployeeWorkDays(year, month, employeeList);
                logger.info("get employee work days success, year:{}, month:{}, employeeList.size:{}, employeeWorkDays.size:{}", year, month, employeeList.size(), employeeWorkDays.size());
                return employeeWorkDays;
            } catch (Exception ex) {
                logger.warning("rpc invoke failed(employeeAttendanceRPC.getEmployeeWorkDays), retry times:{}, year：{}, month:{},  employeeList.size:{}", retry, year, month, employeeList.size(), ex);
                
                // 连续重试失败之后，向上跑出异常
                // 对于没有异常机制的语言，此处应该打印error日志
                if (retry == MAX_RETRY_TIMES) {
                    throw new BusiessException(ex, "rpc invoke failed(employeeAttendanceRPC.getEmployeeWorkDays)");
                }
            }
            retry++;
        }
    }

2.4 日志打印时机的选择

　　由于日志是为了方便我们了解系统当前的运行状况以及定位线上问题，所以日志打印的时机非常重要，如果滥用日志，则会导致日志内容过多，影响问题定位的效率；如果日志打印过少，则容易导致缺少关键日志，导致在线上定位问题时找不到问题根音。因此把握日志打印的时机至关重要，以下是常见的适合打印日志的时机：

1）http调用或者rpc接口调用

　　在程序调用其他服务或者系统的时候，需要打印接口调用参数和调用结果(成功/失败)。

2）程序异常

　　在程序出现exception的时候，要么选择向上抛出异常，要么必须在catch块中打印异常堆栈信息。不过需要注意的是，最好不要重复打印异常日志，比如在catch块里既向上抛出了异常，又去打印错误日志(对外rpc接口函数入口处除外)。

3）特殊的条件分支

　　程序进入到一些特殊的条件分支时，比如特殊的else或者switch分支。比如我们根据工龄计算薪资：

 public double calSalaryByWorkingAge(int age) {
        if (age < 0) {
            logger.error("wrong age value, age:{}", age);
            return 0;
        }
        // ..
    }

　　理论上工龄不可能小于0，所以需要打印出这种非预期情况，当然通过抛出异常的方式也是可行的。

4）关键执行路径及中间状态

　　在一些关键的执行路径以及中间状态也需要记录下关键日志信息，比如一个算法可能分为很多步骤，每隔步骤的中间输出结果是什么，需要记录下来，以方便后续定位跟踪算法执行状态。

5）请求入口和出口

　　在函数或者对外接口的入口/出口处需要打印入口/出口日志，一来方便后续进行日志统计，同时也更加方便进行系统运行状态的监控。

2.5 日志内容与格式

　　日志打印时机决定了能够根据日志去进行问题定位，而日志的内容决定了是否能够根据日志快速找出问题原因，因此日志内容也是至关重要的。通常来说，一行日志应该至少包括以下几个组成部分：

　　logTag、param、exceptionStacktrace

　　logTag为日志标识，用来标识此日志输出的场景或者原因，param为函数调用参数，exceptionStacktrace为异常堆栈。举例说明：

good case

public class HttpClient {
        private static final Logger LOG = LoggerFactory.getLogger(HttpClient.class);

        private static int CONNECT_TIMEOUT = 5000;   // unit ms
        private static int READ_TIMEOUT = 10000;     // unit ms

        public static String sendPost(String url, String param) {
            OutputStream out = null;
            BufferedReader in = null;
            String result = "";
            try {
                URL realUrl = new URL(url);
                URLConnection conn = realUrl.openConnection();
                conn.setDoInput(true);
                conn.setDoOutput(true);
                conn.setConnectTimeout(CONNECT_TIMEOUT);
                conn.setReadTimeout(READ_TIMEOUT);
                conn.setRequestProperty("charset", "UTF-8");
                out = new PrintWriter(conn.getOutputStream());
                out.print(parm);
                out.flush();
                in = new BufferedReader(new InputStreamReader(conn.getInputStream()));
                String line;
                while ((line = in.readLine()) != null) {
                    result += line;
                }
            } catch (Exception ex) {
                // 有关键logTag，有参数信息，有错误堆栈
                LOG.error("post request error!!!, url:[[}], param:[{}]", url, param, ex);
            } finally {
                try {
                    if (out != null) {
                        out.close();
                    }
                    if (in != null) {
                        in.close();
                    }
                } catch (IOException ex) {
                    LOG.error("close stream error!!!, url:[[}], param:[{}]", url, param, ex);
                }
                return result;
            }
        }
    }

bad case

public class HttpClient {
    private static final Logger LOG = LoggerFactory.getLogger(HttpClient.class);

    private static int CONNECT_TIMEOUT = 5000;   // unit ms
    private static int READ_TIMEOUT = 10000;     // unit ms
    
    public static String sendPost(String url, String param) {
        OutputStream out = null;
        BufferedReader in = null;
        String result = "";
        try {
            URL realUrl = new URL(url);
            URLConnection conn = realUrl.openConnection();
            conn.setDoInput(true);
            conn.setDoOutput(true);
            conn.setConnectTimeout(CONNECT_TIMEOUT);
            conn.setReadTimeout(READ_TIMEOUT);
            conn.setRequestProperty("charset", "UTF-8");
            out = new PrintWriter(conn.getOutputStream());
            out.print(parm);
            out.flush();
            in = new BufferedReader(new InputStreamReader(conn.getInputStream()));
            String line;
            while ((line = in.readLine()) != null) {
                result += line;
            }
        } catch (Exception ex) {
            // 没有任何错误信息
            LOG.error("post request error!!!");
        } finally {
            try {
                if (out != null) {
                    out.close();
                }
                if (in != null) {
                    in.close();
                }
            } catch (IOException ex) {
                LOG.error("close stream error!!!");
            }
            return result;
        }
    }
}

　　另外，对于对外http接口或者rpc接口，最好对于每个请求都有requestId，以便跟踪每个请求后续所有的执行路径。

　　最后，推荐一下海子开通的微信公众号，欢迎大家关注：