sprign boot项目实战：日志

日志是运维、排错的一个重要助手，很多人应该都维护过没有日志的项目，知道排查问题是什么感觉。所以搭建基础项目框架时，自然不能少了日志。

日志组件选择

从网上各种搜索对比，在log4j2和logback之间选择了log4j2,综合各处评价，log4j2在性能方法有一定优势。但是在一个项目内使用后就发现，spring boot内log4j2不支持spring profile机制，也就是在本地环境、测试环境、预发布环境、正式环境需要手动切换配置，当前公司的多个环境在相同的服务器上，所以这种方式会导致多个环境的日志生成在了同一个文件内，很不利于问题排查。因此又将日志组件换回了logback，因为对当前公司的项目来说，日志支持profile机制更重要，性能瓶颈绝不在日志这块。

logback配置

spring boot内配置logback还是很简单的，只需要在src/main/resources目录下创建logback-spring.xml，在xml内添加自己的日志配置即可。支持三个环境local、dev、prod的日志配置如下：

<?xml version="1.0" encoding="UTF-8"?>

<configuration scan="true" scanPeriod="30 seconds">
    <property name="LOG_PATH" value="/mnt/diskb/logs"/>

    <springProfile name="local">
        <logger name="com.onecoderspace" level="debug" additivity="true"/>
        <appender name="logfile" class="ch.qos.logback.core.ConsoleAppender">
            <encoder>
                <pattern>%d{yyyy-MM-dd HH:mm:ssS} %5p [%c]:%L-%m%n</pattern>
            </encoder>
        </appender>
    </springProfile>

    <springProfile name="dev">
        <logger name="com.onecoderspace" level="info" additivity="true"/>
        <appender name="logfile" class="ch.qos.logback.core.rolling.RollingFileAppender">
            <file>${LOG_PATH}/projectName/projectName_dev.log</file>
            <append>true</append>
            <encoder>
                <pattern>%d{yyyy-MM-dd HH:mm:ssS} %5p [%c{5}#%M]:%L-%m%n%caller{0}</pattern>
            </encoder>
            <prudent>false</prudent>
            <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
                <!-- daily rollover -->
                <fileNamePattern>${LOG_PATH}/projectName/projectName_dev.%d{yyyy-MM-dd}.log.gz
                </fileNamePattern>
                <maxHistory>30</maxHistory>
            </rollingPolicy>
        </appender>
    </springProfile>

    <springProfile name="prod">
        <logger name="com.onecoderspace" level="info" additivity="true"/>
        <appender name="logfile" class="ch.qos.logback.core.rolling.RollingFileAppender">
            <file>${LOG_PATH}/projectName/projectName.log</file>
            <append>true</append>
            <encoder>
                <pattern>%d{yyyy-MM-dd HH:mm:ssS} %5p [%c{5}#%M]:%L-%m%n%caller{0}</pattern>
            </encoder>
            <prudent>false</prudent>
            <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
                <!-- daily rollover -->
                <fileNamePattern>${LOG_PATH}/projectName/projectName.%d{yyyy-MM-dd}.log.gz
                </fileNamePattern>
                <maxHistory>30</maxHistory>
            </rollingPolicy>
        </appender>
    </springProfile>

    <root level="info">
        <appender-ref ref="logfile" />
    </root>

</configuration>

spring-boot-starter-web内已经包含了logback和slf4j的依赖，所以只要项目依赖了spring-boot-starter-web，就不需要做其他额外的配置了。

日志使用

调用日志时建议使用slf4j，虽然基本不会在后续变更日志组件，但使用slf4j是一个好的习惯。

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
private static Logger logger = LoggerFactory.getLogger(LoginController.class);

debug日志
debug日志建议添加logger.isDebugEnabled()判断，在重要的流程上都留下日志，这样当系统出现问题时，可以通过debug日志，快速定位问题，能代替很多断点调试的时间。

if(logger.isDebugEnabled()){
    logger.debug("user={} login success",username);
}

info日志
比较重要的信息，对于系统运行有比较重要的参考意义，同时不会对性能造成影响，可以在正式环境展示的信息，使用info基本打印，如定时任务运行时间等。

logger.info("end fetcher proxy use time={}", System.currentTimeMillis()- t);

error日志
error日志相对来说是最重要的，但使用时需要注意使用方式，不正确的方式会导致很多信息被隐藏。可以参考如下方式：

logger.error(String.format("error msg ,arg1=%s,arg2=%s",arg1,arg2), e);

• 尽可能的带上异常发生时的参数，这个对排查问题很有意义
• 打印异常的完整堆栈信息，仅打印e.getMessage()会导致很多信息被隐藏
• 只在异常发生时或明确的业务错误时使用error，不要用error来打印调试、普通信息

总结

1. spring boot项目内日志组件选择logback比较好，内嵌的日志组件，支持profile机制；
2. logback配置方式为在src/main/resources目录下创建logback-spring.xml，配置内容参考上文；
3. 调用日志时使用slf4j，注意合理使用日志级别
4. 注意以下几点tips

tips

1、 应用日志尽量放在数据盘上，不要放在系统盘上，遇到了不止一次日志写满系统盘导致服务暂停的情况
2、 技术负责人定好日志规范，在代码review时指出几次日志使用的问题，能够很快让良好使用日志成为团队的习惯
3、 正式环境的日志基本最低为info，通常可以调整为warn或error
4、 在while循环内有异常捕获时，注意当异常发生时，不能无限打印日志，如下代码：

while (flag) {
    try {
        byte[] bb = _queue.poll(1, TimeUnit.SECONDS);
        if (bb != null) {
            @SuppressWarnings("unchecked")
            Map<String, Object> m = JacksonSupport.decode1(new ByteArrayInputStream(bb), Map.class);
            E event = _consumer.getEventType().newInstance();
            event.fromMap(m);
            _consumer.onEvent(event);
        }
    } catch (Exception e) {
        logger.error("redis queue poll due to error", e);
    }
}

从基于redis开发的一个blockingQueue内获取元素进行消费，代码运行了一年多十分正常，但是有一次几乎把磁盘写满了，因为当时运维调整，redis停掉了， _queue.poll这里就开始抛异常，然后下面就狂写日志，一直把磁盘写满。类似这样的地方，可以进行一个计数，连续错误达到多少次，就终止循环并以某些方式提醒运维人员。
5、不要使用System.out.println()，建议隔段时间全局搜索一次，发现了就在小组会议上提一下，很快这种现象就会杜绝