好久以前,有个朋友问我,若是一个老项目让你接手去进行后续维护,你会先从哪里入手、让本身更快地上手项目?当时我没有特别正面去回答这个朋友的问题,我说:一个老项目是否容易上手,一个很是关键的地方就是这个项目的日志是否打得足够好。由于一般来讲,一个老项目相对比较稳定了,后续大几率不会有比较大的变动和改动,那么对于这样的项目,核心就是“维稳”。可是任何人都没法保证项目在线上运行时不会出线上故障,在出现线上问题或者故障时,如何快速止损就是第一要义,而日志在止损过程当中就扮演着很是重要的角色。日志打的足够明了清晰,能够帮助开发和运维人员快速定位问题,继而决定采起何种方案进行止损。html
今天就让咱们一块儿来聊一聊如何把项目程序日志打“好”。如下是本文大纲目录:java
一.为什么须要规范地打印程序日志?nginx
二.如何规范地打印程序日志? git
如有不正之处请多多谅解,并欢迎批评指正。web
请尊重做者劳动成果,转载请标明原文连接:算法
https://www.cnblogs.com/dolphin0520/p/10396894.htmlsql
咱们平时在写程序代码过程当中,通常会把主要精力集中在功能实现上,每每会忽视日志的重要性,然而日志在系统上线后是极其重要的,由于系统上线后,只有经过日志才能了解当前系统的运行状态,在出现线上故障时,日志是否足够清晰明了决定了是否可以快速找到止损方案。咱们能够看一下下面这段代码:数据库
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!!!”错误,此时假如看到这样的日志你可能彻底不知道到底是什么缘由致使的,还得继续经过一些其余的手段来定位具体缘由。bash
假如打印的错误日志是这样的:服务器
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,则很容易统计,不然须要从新上线加日志才能统计。
所以,你们在平常编写代码过程当中要注重日志书写的规范性,让它发挥出它应有的价值,在辅助保障咱们服务稳定运行的同时,可以有效提高后期系统维护效率。
接下来,咱们从如下几个方面来谈谈如何规范地打印日志。
一般来讲日志文件的命名可包括如下几个关键信息:
类型标识(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个参数切记必定要设置,若是没有设置,则颇有可能会出现把线上机器磁盘打满的状况。
日志的级别一般有如下几种:
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++; } }复制代码
因为日志是为了方便咱们了解系统当前的运行情况以及定位线上问题,因此日志打印的时机很是重要,若是滥用日志,则会致使日志内容过多,影响问题定位的效率;若是日志打印过少,则容易致使缺乏关键日志,致使在线上定位问题时找不到问题根音。所以把握日志打印的时机相当重要,如下是常见的适合打印日志的时机:
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)请求入口和出口
在函数或者对外接口的入口/出口处须要打印入口/出口日志,一来方便后续进行日志统计,同时也更加方便进行系统运行状态的监控。
日志打印时机决定了可以根据日志去进行问题定位,而日志的内容决定了是否可以根据日志快速找出问题缘由,所以日志内容也是相当重要的。一般来讲,一行日志应该至少包括如下几个组成部分:
logTag、param、exceptionStacktrace
logTag为日志标识,用来标识此日志输出的场景或者缘由,param为函数调用参数,exceptionStacktrace为异常堆栈。举例说明:
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; } } } 复制代码
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,以便跟踪每一个请求后续全部的执行路径。
参考文章: