惊讶！我定的日志规范被CTO在全公司推广了

时间 2019-12-28

原文原文链接

打印日志是一门艺术，但长期被开发同窗所忽视。日志就像车辆保险，没人愿意为保险付钱，可是一旦出了问题都又想有保险可用。咱们打印日志的时候都很随意，但是用的时候会吐槽各类 SB 包括本身！写好每一条日志吧，与君共勉！html

日志

日志是什么？

日志，维基百科的定义是记录服务器等电脑设备或软件的运做。java

日志文件提供精确的系统记录，根据日志最终定位到错误详情和根源。日志的特色是，它描述一些离散的（不连续的）事件。例如：应用经过一个滚动的文件输出 INFO 或 ERROR 信息，并经过日志收集系统，存储到一些存储引擎（Elasticsearch）中方便查询。git

日志有什么用？

在上文中咱们解释了日志的做用是提供精准的系统记录方便根因分析。那么具体在哪些具体方面它能够发挥做用？github
打印调试：便可以用日志来记录变量或者某一段逻辑。记录程序运行的流程，即程序运行了哪些代码，方便排查逻辑问题。spring
问题定位：程序出异常或者出故障时快速的定位问题，方便后期解决问题。由于线上生产环境没法 debug，在测试环境去模拟一套生产环境，费时费力。因此依靠日志记录的信息定位问题，这点很是重要。还能够记录流量，后期能够经过 ELK（包括 EFK 进行流量统计）。数据库
用户行为日志：记录用户的操做行为，用于大数据分析，好比监控、风控、推荐等等。这种日志，通常是给其余团队分析使用，并且多是多个团队，所以通常会有必定的格式要求，开发者应该按照这个格式来记录，便于其余团队的使用。固然，要记录哪些行为、操做，通常也是约定好的，所以，开发者主要是执行的角色。编程
根因分析（甩锅必备）：即在关键地方记录日志。方便在和各个终端定位问题时，别人说时你的程序问题，你能够义正词严的拿出你的日志说，看，我这里运行了，状态也是对的。这样，对方就会乖乖去定位他的代码，而不是互相推脱。json

何时记录日志？

上文说了日志的重要性，那么何时须要记录日志。安全

系统初始化：系统或者服务的启动参数。核心模块或者组件初始化过程当中每每依赖一些关键配置，根据参数不一样会提供不同的服务。务必在这里记录 INFO 日志，打印出参数以及启动完成态服务表述。
编程语言提示异常：现在各种主流的编程语言都包括异常机制，业务相关的流行框架有完整的异常模块。这类捕获的异常是系统告知开发人员须要加以关注的，是质量很是高的报错。应当适当记录日志，根据实际结合业务的状况使用 WARN 或者 ERROR 级别。
业务流程预期不符：除开平台以及编程语言异常以外，项目代码中结果与指望不符时也是日志场景之一，简单来讲全部流程分支均可以加入考虑。取决于开发人员判断可否容忍情形发生。常见的合适场景包括外部参数不正确，数据处理问题致使返回码不在合理范围内等等。
系统核心角色，组件关键动做：系统中核心角色触发的业务动做是须要多加关注的，是衡量系统正常运行的重要指标，建议记录 INFO 级别日志，好比电商系统用户从登陆到下单的整个流程；微服务各服务节点交互；核心数据表增删改；核心组件运行等等，若是日志频度高或者打印量特别大，能够提炼关键点 INFO 记录，其他酌情考虑 DEBUG 级别。
第三方服务远程调用：微服务架构体系中有一个重要的点就是第三方永远不可信，对于第三方服务远程调用建议打印请求和响应的参数，方便在和各个终端定位问题，不会由于第三方服务日志的缺失变得手足无措。

日志打印

Slf4j & Logback

Slf4j 英文全称为 “ Simple Logging Facade for Java ”，为 Java 提供的简单日志门面。Facade 门面，更底层一点说就是接口。它容许用户以本身的喜爱，在工程中经过 Slf4j 接入不一样的日志系统。bash

Logback 是 Slf4j 的原生实现框架，一样也是出自 Log4j 一我的之手，但拥有比 Log4j 更多的优势、特性和更作强的性能，Logback 相对于 Log4j 拥有更快的执行速度。基于咱们先前在 Log4j 上的工做，Logback 重写了内部的实现，在某些特定的场景上面，甚至能够比以前的速度快上 10 倍。在保证 Logback 的组件更加快速的同时，同时所需的内存更加少。

日志文件

日志文件放置于固定的目录中，按照必定的模板进行命名，推荐的日志文件名称：

当前正在写入的日志文件名：<应用名>[-<功能名>].log
如：example-server-book-service-access.log
已经滚入历史的日志文件名：<应用名>[-<功能名>].yyyy-MM-dd-hh.[滚动号].log
复制代码

如：example-server-book-service-access.2019-12-01-10.1.log

日志变量定义

推荐使用 lombok（代码生成器）注解 @lombok.extern.slf4j.Slf4j 来生成日志变量实例。

<!-- https://mvnrepository.com/artifact/org.projectlombok/lombok -->
<dependency>
    <groupId>org.projectlombok</groupId>
    <artifactId>lombok</artifactId>
    <version>1.18.10</version>
    <scope>provided</scope>
</dependency>
复制代码

代码示例

import lombok.extern.slf4j.Slf4j;

@Slf4j
public class LogTest {

    public static void main(String[] args) {
        log.info("this is log test");
    }
    
}
复制代码

日志配置

日志记录采用分级记录，级别与日志文件名相对应，不一样级别的日志信息记录到不一样的日志文件中。若有特殊格式日志，如 access log，单独使用一个文件，请注意避免重复打印（可以使用 additivity**="false"** 避免）。

参数占位格式

使用参数化形式 {} 占位，[] 进行参数隔离，这样的好处是可读性更高，并且只有真正准备打印的时候才会处理参数。

// 正确示例，必须使用参数化信息的方式
log.debug("order is paying with userId:[{}] and orderId : [{}]",userId, orderId);
// 错误示例，不要进行字符串拼接,那样会产生不少 String 对象，占用空间，影响性能。及日志级别高于此级别也会进行字符串拼接逻辑。
log.debug("order is paying with userId: " + userId + " and orderId: " + orderId);
复制代码

日志的基本格式

日志时间

做为日志产生的日期和时间，这个数据很是重要，通常精确到毫秒。

yyyy-MM-dd HH:mm:ss.SSS
复制代码

日志级别

日志的输出都是分级别的，不一样的设置不一样的场合打印不一样的日志。

主要使用以下的四个级别：

DEBUG：DEUBG 级别的主要输出调试性质的内容，该级别日志主要用于在开发、测试阶段输出。该级别的日志应尽量地详尽，开发人员能够将各种详细信息记录到 DEBUG 里，起到调试的做用，包括参数信息，调试细节信息，返回值信息等等，便于在开发、测试阶段出现问题或者异常时，对其进行分析。
INFO：INFO 级别的主要记录系统关键信息，旨在保留系统正常工做期间关键运行指标，开发人员能够将初始化系统配置、业务状态变化信息，或者用户业务流程中的核心处理记录到INFO日志中，方便平常运维工做以及错误回溯时上下文场景复现。建议在项目完成后，在测试环境将日志级别调成 INFO，而后经过 INFO 级别的信息看看是否能了解这个应用的运用状况，若是出现问题后是否这些日志可否提供有用的排查问题的信息。
WARN：WARN 级别的主要输出警告性质的内容，这些内容是能够预知且是有规划的，好比，某个方法入参为空或者该参数的值不知足运行该方法的条件时。在 WARN 级别的时应输出较为详尽的信息，以便于过后对日志进行分析。
ERROR：ERROR 级别主要针对于一些不可预知的信息，诸如：错误、异常等，好比，在 catch 块中抓获的网络通讯、数据库链接等异常，若异常对系统的整个流程影响不大，可使用 WARN 级别日志输出。在输出 ERROR 级别的日志时，尽可能多地输出方法入参数、方法执行过程当中产生的对象等数据，在带有错误、异常对象的数据时，须要将该对象一并输出。

DEBUG / INFO 的选择

DEBUG 级别比 INFO 低，包含调试时更详细的了解系统运行状态的东西，好比变量的值等等，均可以输出到 DEBUG 日志里。 INFO 是在线日志默认的输出级别，反馈系统的当前状态给最终用户看的。输出的信息，应该对最终用户具备实际意义的。从功能角度上说，INFO 输出的信息能够看做是软件产品的一部分，因此须要谨慎对待，不可随便输出。若是这条日志会被频繁打印或者大部分时间对于纠错起不到做用，就应当考虑下调为 DEBUG 级别。

因为 DEBUG 日志打印量远大于 INFO，出于前文日志性能的考虑，若是代码为核心代码，执行频率很是高，务必推敲日志设计是否合理，是否须要下调为 DEBUG 级别日志。
注意日志的可读性，不妨在写完代码 review 这条日志是否通顺，可否提供真正有意义的信息。
日志输出是多线程公用的，若是有另一个线程正在输出日志，上面的记录就会被打断，最终显示输出和预想的就会不一致。

WARN / ERROR 的选择

当方法或者功能处理过程当中产生不符合预期结果或者有框架报错时能够考虑使用，常见问题处理方法包括：

增长判断处理逻辑，尝试本地解决：增长逻辑判断吞掉报警永远是最优选择抛出异常，交给上层逻辑解决
抛出异常，交给上层逻辑解决
记录日志，报警提醒
使用返回码包装错误作返回

通常来讲，WARN 级别不会短信报警，ERROR 级别则会短信报警甚至电话报警，ERROR 级别的日志意味着系统中发生了很是严重的问题，必须有人立刻处理，好比数据库不可用，系统的关键业务流程走不下去等等。错误的使用反而带来严重的后果，不区分问题的重要程度，只要有问题就error记录下来，其实这样是很是不负责任的，由于对于成熟的系统，都会有一套完整的报错机制，那这个错误信息何时须要发出来，不少都是依据单位时间内 ERROR 日志的数量来肯定的。

强调ERROR报警

ERROR 级别的日志打印一般伴随报警通知。ERROR的报出应该伴随着业务功能受损，即上面提到的系统中发生了很是严重的问题，必须有人立刻处理。

ERROR日志目标

给处理者直接准确的信息：ERROR 信息造成自身闭环。

问题定位：

发生了什么问题，哪些功能受到影响
获取帮助信息：直接帮助信息或帮助信息的存储位置
经过报警知道解决方案或者找何人解决

线程名称

输出该日志的线程名称，通常在一个应用中一个同步请求由同一线程完成，输出线程名称能够在各个请求产生的日志中进行分类，便于分清当前请求上下文的日志。

opentracing 标识

在分布式应用中，用户的一个请求会调用若干个服务完成，这些服务可能仍是嵌套调用的，所以完成一个请求的日志并不在一个应用的日志文件，而是分散在不一样服务器上不一样应用节点的日志文件中。该标识是为了串联一个请求在整个系统中的调用日志。

惟一字符串（trace id）
调用层级（span id）

经过搜索 trace id 就能够查到这个 trace id 标识的请求在整个系统中流转（处理）过程当中产生的全部日志。

biz 标识

在业务开发中，咱们的日志都是和业务相关联的，有时候是须要根据用户或者业务作聚类的，所以一次请求若是能够经过某项标识作聚类的时候，能够将聚类标识打印到日志中。

用户标识（user id）
业务标识（biz id）

日志记录器名称

日志记录器名称通常使用类名，日志文件中能够输出简单的类名便可，看实际状况是否须要使用包名和行号等信息。主要用于看到日志后到哪一个类中去找这个日志输出，便于定位问题所在。

日志内容

禁用 System.out.println 和 System.err.println

变参替换日志拼接

输出日志的对象，应在其类中实现快速的 toString 方法，以便于在日志输出时仅输出这个对象类名和 hashCode

预防空指针:不要在日志中调用对象的方法获取值，除非确保该对象确定不为 null，不然颇有可能会由于日志的问题而致使应用产生空指针异常。

异常堆栈

异常堆栈通常会出如今 ERROR 或者 WARN 级别的日志中，异常堆栈含有方法调用链的系统，以及异常产生的根源。异常堆栈的日志属于上一行日志的，在日志收集时须要将其划至上一行中。

最佳实践

日志格式

2019-12-01 00:00:00.000|pid|log-level|[svc-name,trace-id,span-id,user-id,biz-id]|thread-name|package-name.class-name : log message
复制代码

时间
pid，pid
log-level，日志级别
svc-name，应用名称
trace-id，调用链标识
span-id，调用层级标识
user-id，用户标识
biz-id，业务标识
thread-name，线程名称
package-name.class-name，日志记录器名称
log message，日志消息体

日志模块扩展

日志模块是基于如下技术点作扩展的。

Slf4j MDC 实现原理（暂不开展详解，若有兴趣私下沟通）
Opentracing Scope 原理（暂不开展详解，若有兴趣私下沟通）

在每一个 tracing 链路中，将 Opentracing Scope 中的上下文信息放置 MDC 中，根据 Spring Boot Logging 扩展接口扩展的取值逻辑 **logging.pattern.level **的取值逻辑。

相关源码参考

Spring Cloud Sleuth

[Spring Cloud Sleuth]github.com/spring-clou…

修改 logback 配置文件中每一个 appender 的 pattern 为如下默认值便可实现标准化。

%d{${LOG_DATEFORMAT_PATTERN:-yyyy-MM-dd HH:mm:ss.SSS}}|${PID:- }|%level|${LOG_LEVEL_PATTERN:-%5p}|%t|%-40.40logger{39}: %msg%n
复制代码

logback.xml 节选

<configuration>
<property name="LOG_PATH"
          value="${LOG_PATH:-${LOG_TEMP:-${java.io.tmpdir:-/tmp}}}"/>

<springProperty scope="context" name="APP_NAME"
                source="spring.application.name" defaultValue="spring-boot-fusion"/>
<!-- 全局统一 pattern -->
<property name="LOG_PATTERN"
          value="%d{${LOG_DATEFORMAT_PATTERN:-yyyy-MM-dd HH:mm:ss.SSS}}|${PID:- }|%level|${LOG_LEVEL_PATTERN:-%5p}|%t|%-40.40logger{39}: %msg%n"/>
<!-- 输出模式 file,滚动记录文件，先将日志文件指定到文件，当符合某个条件时，将日志记录到其余文件 -->
<appender name="fileInfo" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <!--被写入的文件名，能够是相对目录，也能够是绝对目录，若是上级目录不存在会自动建立，没有默认值。-->
    <file>${LOG_PATH}/${APP_NAME}-info.log</file>
    <!--滚动策略  基于时间的分包策略 -->
    <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
        <!-- yyyy-MM-dd 时间策略则为一天一个文件 -->
        <FileNamePattern>${LOG_PATH}/${APP_NAME}-info.%d{yyyy-MM-dd-HH}.%i.log</FileNamePattern>
        <!--日志文件保留小时数-->
        <MaxHistory>48</MaxHistory>
        <maxFileSize>1GB</maxFileSize>
        <totalSizeCap>20GB</totalSizeCap>
    </rollingPolicy>
    <!--  layout 负责把事件转换成字符串，格式化的日志信息的输出 -->
    <layout class="ch.qos.logback.classic.PatternLayout">
        <pattern>${LOG_PATTERN}</pattern>
    </layout>
    <!--级别过滤器，根据日志级别进行过滤。若是日志级别等于配置级别，过滤器会根据onMath 和 onMismatch接收或拒绝日志-->
    <filter class="ch.qos.logback.classic.filter.LevelFilter">
        <!--设置过滤级别-->
        <level>INFO</level>
        <!--用于配置符合过滤条件的操做-->
        <onMatch>ACCEPT</onMatch>
        <!--用于配置不符合过滤条件的操做-->
        <onMismatch>DENY</onMismatch>
    </filter>
</appender>
</configuration>
复制代码

代码使用示例：

@Override
public Result<PagingObject<SimpleResponse>> page(@RequestParam(value = "page-num", defaultValue = "1") int pageNum,
                                                 @RequestParam(value = "page-size", defaultValue = "10") int pageSize) {
    LogStandardUtils.putUserId("userId123");
    LogStandardUtils.putBizId("bizId321");
    producerService.sendMsg("xxx");
    simpleClient.page(pageNum, pageSize);
    return new Result<>(simpleService.page(pageNum, pageSize));
}
复制代码

日志记录

2019-12-04 16:29:08.223|43546|INFO|[example-server-book-service,ac613cff04bac8b1,4a9adc10fdf0eb5,userId123,bizId321]|XNIO-1 task-4|c.n.u.concurrent.ShutdownEnabledTimer   : Shutdown hook installed for: NFLoadBalancer-PingTimer-example-server-order-service
2019-12-04 16:29:08.224|43546|INFO|[example-server-book-service,ac613cff04bac8b1,4a9adc10fdf0eb5,userId123,bizId321]|XNIO-1 task-4|c.netflix.loadbalancer.BaseLoadBalancer : Client: example-server-order-service instantiated a LoadBalancer: DynamicServerListLoadBalancer:{NFLoadBalancer:name=example-server-order-service,current list of Servers=[],Load balancer stats=Zone stats: {},Server stats: []}ServerList:null
2019-12-04 16:29:08.234|43546|INFO|[example-server-book-service,ac613cff04bac8b1,4a9adc10fdf0eb5,userId123,bizId321]|XNIO-1 task-4|c.n.l.DynamicServerListLoadBalancer     : Using serverListUpdater PollingServerListUpdater
2019-12-04 16:29:08.247|43546|INFO|[example-server-book-service,ac613cff04bac8b1,4a9adc10fdf0eb5,userId123,bizId321]|XNIO-1 task-4|c.n.l.DynamicServerListLoadBalancer     : DynamicServerListLoadBalancer for client example-server-order-service initialized: DynamicServerListLoadBalancer:{NFLoadBalancer:name=example-server-order-service,current list of Servers=[],Load balancer stats=Zone stats: {},Server stats: []}ServerList:ConsulServerList{serviceId='example-server-order-service', tag=null}
2019-12-04 16:29:08.329|43546|WARN|[example-server-book-service,ac613cff04bac8b1,4a9adc10fdf0eb5,userId123,bizId321]|XNIO-1 task-4|c.p.f.l.ctl.common.rule.StrategyRule    : No up servers available from load balancer: DynamicServerListLoadBalancer:{NFLoadBalancer:name=example-server-order-service,current list of Servers=[],Load balancer stats=Zone stats: {},Server stats: []}ServerList:ConsulServerList{serviceId='example-server-order-service', tag=null}
2019-12-04 16:29:08.334|43546|WARN|[example-server-book-service,ac613cff04bac8b1,4a9adc10fdf0eb5,userId123,bizId321]|XNIO-1 task-4|c.p.f.l.ctl.common.rule.StrategyRule    : No up servers available from load balancer: DynamicServerListLoadBalancer:{NFLoadBalancer:name=example-server-order-service,current list of Servers=[],Load balancer stats=Zone stats: {},Server stats: []}ServerList:ConsulServerList{serviceId='example-server-order-service', tag=null}
2019-12-04 16:29:08.342|43546|ERROR|[example-server-book-service,ac613cff04bac8b1,4a9adc10fdf0eb5,userId123,bizId321]|XNIO-1 task-4|c.p.f.w.c.advice.ExceptionHandlerAdvice : 当前程序进入到异常捕获器，出错的 url 为：[ http://127.0.0.1:10011/simples ]，出错的参数为：[ {"querystring":"{}","payload":""} ]
java.lang.RuntimeException: com.netflix.client.ClientException: Load balancer does not have available server for client: example-server-order-service
复制代码

日志服务

SLS日志服务

日志服务（简称 SLS）是针对日志类数据的一站式服务，在阿里巴巴集团经历大量大数据场景锤炼而成。您无需开发就能快捷完成日志数据采集、消费、投递以及查询分析等功能，提高运维、运营效率，创建 DT 时代海量日志处理能力。

project

项目、管理日志基础单元，服务日志建议一个环境建为一个 Project，这样日志记录是总体一个闭环，日志记录随整个环境内的服务调用产生。

logstore

日志库，日志库建议按照日志类型分为不一样的，如特定格式的 access 日志，以及 info / warn / error 日志，特定格式能够配置更为方面的索引以及告警设置。

注意：请勿按照应用服务区分为不一样的 logstore，在微服务架构中，一次请求交叉了多个应用服务，日志是散落在各个应用服务中的，按照服务区分 logstore，须要开发同窗十分了解应用运行情况和调用拓扑图，这点每每是不具有的。

实时采集与消费

功能：

经过ECS、容器、移动端、开源软件、JS等接入实时日志数据（例如Metric、Event、BinLog、TextLog、Click等）。
提供实时消费接口，与实时计算及服务对接。

用途：数据清洗（ETL）、流计算（Stream Compute）、监控与报警、机器学习与迭代计算。

查询分析

实时索引、查询分析数据。

查询：关键词、模糊、上下文、范围。
统计：SQL聚合等丰富查询手段。
可视化：Dashboard + 报表功能。
对接：Grafana、JDBC/SQL92。

用途：DevOps / 线上运维，日志实时数据分析，安全诊断与分析，运营与客服系统。

消费投递

稳定可靠的日志投递。将日志中枢数据投递至存储类服务进行存储。支持压缩、自定义Partition、以及行列等各类存储方式。

用途：数据仓库 + 数据分析、审计、推荐系统与用户画像。

告警

日志服务的告警功能基于仪表盘中的查询图表实现。在日志服务控制台查询页面或仪表盘页面设置告警规则，并指定告警规则的配置、检查条件和通知方式。设置告警后，日志服务按期对仪表盘的查询结果进行检查，检查结果知足预设条件时发送告警通知，实现实时的服务状态监控。

最佳实践

日志服务功能至关强大，想用好日志服务能够参看：

help.aliyun.com/document_de…

ELK 通用日志解决方案

ELK 是 Elasticsearch、Logstash、Kibana 三大开源框架首字母大写简称。市面上也被成为 Elastic Stack。其中 Elasticsearch 是一个基于 Lucene、分布式、经过 Restful 方式进行交互的近实时搜索平台框架。像相似百度、谷歌这种大数据全文搜索引擎的场景均可以使用 Elasticsearch 做为底层支持框架，可见 Elasticsearch 提供的搜索能力确实强大，市面上不少时候咱们简称 Elasticsearch 为 es。Logstash 是 ELK 的中央数据流引擎，用于从不一样目标（文件/数据存储/MQ）收集的不一样格式数据，通过过滤后支持输出到不一样目的地（文件/ MQ / Redis / Elasticsearch / Kafka 等）。Kibana 能够将 Elasticsearch 的数据经过友好的页面展现出来，提供实时分析的功能。

实践说明

普通格式日志

2019-11-26 15:01:03.332|1543|INFO|[example-server-book-service,28f019d57b8336ab,630697c7f34ca4fa,105,45982043|XNIO-1 task-42]|c.p.f.w.pay.PayServiceImpl     : order is paying with userId: 105 and orderId: 45982043
复制代码

普通日志前缀是固定的，能够固定分词索引，方便更快的查询分析。

特定格式日志

以 access 日志为例

2019-11-26 15:01:03.332|1543|INFO|[example-server-book-service,28f019d57b8336ab,630697c7f34ca4fa,105,45982043|XNIO-1 task-42]|c.p.f.w.logging.AccessLoggingFilter     : 
> url: http://liweichao.com:10011/actuator/health
> http-method: GET
> request-header: [Accept:"text/plain, text/*, */*", Connection:"close", User-Agent:"Consul Health Check", Host:"liweichao.com:10011", Accept-Encoding:"gzip"]
> request-time: 2019-11-26 15:01:03.309
> querystring: -
> payload: -
> extra-param: -

< response-time: 2019-11-26 15:01:03.332
< take-time: 23
< http-status: 200
< response-header: [content-type:"application/vnd.spring-boot.actuator.v2+json;charset=UTF-8", content-size:"15"]
< response-data: {"status":"UP"}
复制代码

特定格式日志可按格式建立索引更方便聚焦查询分析和告警，如根据 take-time，http-status，biz-code 等值。

参考文献

[ Java日志记录最佳实践 ](www.jianshu.com/p/546e9aace…
[ 别在 Java 代码里乱打日志了，这才是打印日志的正确姿式！ ](mp.weixin.qq.com/s/hJvkRlt9x…
[ 日志服务 ](help.aliyun.com/product/289…
[ Spring Boot Logging ](docs.spring.io/spring-boot…
[ Spring Cloud Sleuth ](github.com/spring-clou…
[ Opentracing ](github.com/opentracing

做者说明

来自读者投稿，有好的文章欢迎联系我微信 jihuan900