打印日志是一门艺术,但长期被开发同学所忽视。日志就像车辆保险,没人愿意为保险付钱,但是一旦出了问题都又想有保险可用。我们打印日志的时候都很随意,可是用的时候会吐槽各种 SB 包括自己!写好每一条日志吧,与君共勉!
日志,维基百科的定义是记录服务器等电脑设备或软件的运作。
日志文件提供精确的系统记录,根据日志最终定位到错误详情和根源。日志的特点是,它描述一些离散的(不连续的)事件。 例如:应用通过一个滚动的文件输出 INFO 或 ERROR 信息,并通过日志收集系统,存储到一些存储引擎(Elasticsearch)中方便查询。
在上文中我们解释了日志的作用是提供精准的系统记录方便根因分析。那么具体在哪些具体方面它可以发挥作用?
打印调试:即可以用日志来记录变量或者某一段逻辑。记录程序运行的流程,即程序运行了哪些代码,方便排查逻辑问题。
问题定位:程序出异常或者出故障时快速的定位问题,方便后期解决问题。因为线上生产环境无法 debug,在测试环境去模拟一套生产环境,费时费力。所以依靠日志记录的信息定位问题,这点非常重要。还可以记录流量,后期可以通过 ELK(包括 EFK 进行流量统计)。
用户行为日志:记录用户的操作行为,用于大数据分析,比如监控、风控、推荐等等。这种日志,一般是给其他团队分析使用,而且可能是多个团队,因此一般会有一定的格式要求,开发者应该按照这个格式来记录,便于其他团队的使用。当然,要记录哪些行为、操作,一般也是约定好的,因此,开发者主要是执行的角色。
根因分析(甩锅必备):即在关键地方记录日志。方便在和各个终端定位问题时,别人说时你的程序问题,你可以理直气壮的拿出你的日志说,看,我这里运行了,状态也是对的。这样,对方就会乖乖去定位他的代码,而不是互相推脱。
上文说了日志的重要性,那么什么时候需要记录日志。
Slf4j 英文全称为 “ Simple Logging Facade for Java ”,为 Java 提供的简单日志门面。Facade 门面,更底层一点说就是接口。它允许用户以自己的喜好,在工程中通过 Slf4j 接入不同的日志系统。
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 / INFO 的选择
DEBUG 级别比 INFO 低,包含调试时更详细的了解系统运行状态的东西,比如变量的值等等,都可以输出到 DEBUG 日志里。 INFO 是在线日志默认的输出级别,反馈系统的当前状态给最终用户看的。输出的信息,应该对最终用户具有实际意义的。从功能角度上说,INFO 输出的信息可以看作是软件产品的一部分,所以需要谨慎对待,不可随便输出。如果这条日志会被频繁打印或者大部分时间对于纠错起不到作用,就应当考虑下调为 DEBUG 级别。
WARN / ERROR 的选择
当方法或者功能处理过程中产生不符合预期结果或者有框架报错时可以考虑使用,常见问题处理方法包括:
一般来说,WARN 级别不会短信报警,ERROR 级别则会短信报警甚至电话报警,ERROR 级别的日志意味着系统中发生了非常严重的问题,必须有人马上处理,比如数据库不可用,系统的关键业务流程走不下去等等。错误的使用反而带来严重的后果,不区分问题的重要程度,只要有问题就error记录下来,其实这样是非常不负责任的,因为对于成熟的系统,都会有一套完整的报错机制,那这个错误信息什么时候需要发出来,很多都是依据单位时间内 ERROR 日志的数量来确定的。
强调ERROR报警
ERROR日志目标
问题定位:
输出该日志的线程名称,一般在一个应用中一个同步请求由同一线程完成,输出线程名称可以在各个请求产生的日志中进行分类,便于分清当前请求上下文的日志。
在分布式应用中,用户的一个请求会调用若干个服务完成,这些服务可能还是嵌套调用的,因此完成一个请求的日志并不在一个应用的日志文件,而是分散在不同服务器上不同应用节点的日志文件中。该标识是为了串联一个请求在整个系统中的调用日志。
通过搜索 trace id 就可以查到这个 trace 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
日志模块是基于以下技术点做扩展的。
在每个 tracing 链路中,将 Opentracing Scope 中的上下文信息放置 MDC 中,根据 Spring Boot Logging 扩展接口扩展的取值逻辑 **logging.pattern.level **的取值逻辑。
相关源码参考
[Spring Cloud Sleuth]https://github.com/spring-cloud/spring-cloud-sleuth/blob/master/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/log/Slf4jCurrentTraceContext.java
修改 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)是针对日志类数据的一站式服务,在阿里巴巴集团经历大量大数据场景锤炼而成。您无需开发就能快捷完成日志数据采集、消费、投递以及查询分析等功能,提升运维、运营效率,建立 DT 时代海量日志处理能力。
项目、管理日志基础单元,服务日志建议一个环境建为一个 Project,这样日志记录是整体一个闭环,日志记录随整个环境内的服务调用产生。
日志库,日志库建议按照日志类型分为不同的,如特定格式的 access 日志,以及 info / warn / error 日志,特定格式可以配置更为方面的索引以及告警设置。
注意:请勿按照应用服务区分为不同的 logstore,在微服务架构中,一次请求交叉了多个应用服务,日志是散落在各个应用服务中的,按照服务区分 logstore,需要开发同学十分了解应用运行状况和调用拓扑图,这点往往是不具备的。
功能:
用途:数据清洗(ETL)、流计算(Stream Compute)、监控与报警、 机器学习与迭代计算。
实时索引、查询分析数据。
用途:DevOps / 线上运维,日志实时数据分析,安全诊断与分析,运营与客服系统。
稳定可靠的日志投递。将日志中枢数据投递至存储类服务进行存储。支持压缩、自定义Partition、以及行列等各种存储方式。
用途:数据仓库 + 数据分析、审计、推荐系统与用户画像。
日志服务的告警功能基于仪表盘中的查询图表实现。在日志服务控制台查询页面或仪表盘页面设置告警规则,并指定告警规则的配置、检查条件和通知方式。设置告警后,日志服务定期对仪表盘的查询结果进行检查,检查结果满足预设条件时发送告警通知,实现实时的服务状态监控。
阿里云的日志服务功能相当强大,想用好日志服务可以参看:
https://help.aliyun.com/document_detail/29090.html?spm=a2c4g.11186623.6.1079.4edd3aabvs50OW
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 等值。
来自读者投稿,有好的文章欢迎联系我微信 jihuan900
手机扫一扫
移动阅读更方便
你可能感兴趣的文章