§1 综述
日志和异常是项目正常运行时,唯二的可以直接窥探代码运行状态的手段(暂时不考虑一些监控框架)。
因为二者略有互通且通常异常时必然伴有日志,因此一起说明。
此文档,前面用于说明项目中常见套路或概念,后面则给出各场景下示例
§1.1 记录日志的目的
- 指示,记录项目中各个机制的运行情况
- 接口,记录接口执行情况
- 流程报告,记录重要流程执行节点和关键步骤数据
- 异常,记录异常信息
§1.2 记录日志的粒度
- 访问日志,又称系统日志。按其粒度可以分为审计日志、操作日志和接口日志,操作日志只记录用户对系统的直接请求(可以理解为controller+openservice),后者会涉及所有关键接口的访问信息,审计日志则相当于操作日志的摘要(即,基本不涉及其中的数据)或定性记录。无论哪种级别的访问日志,都建议使用日志管理框架、切面结合注解之类的方式实现,严禁侵入业务。但特殊组件的日志推荐使用业务日志代替。持久化可以使用数据库、缓存等。
- 业务日志,关键日志。业务中产生的需要记录的信息都属于此类。需要注意直接操作某功能触发的异常而导致需要记录的日志也可以算作访问日志。一般通过log4j,logback等日志框架记录。按照记录的量和日志级别,可以自由选择保存周期
- 数据日志,数据变更日志,历史日志。一般不需要做到这种粒度,用于记录核心数据从被创建到最后状态所经历的所有变更和数据变化。若真有使用需要,可以通过历史表(业务侵略),监听数据库binlog进行(推荐,但比较重)。持久化一般通过传统日志文件,es,hbase等,通常有对应的解析手段
§1.3 异常的分类
- 普通异常,一般是内部调用的api抛出的异常,如 IOException 一般只做通用处理
- 运行时异常,最臭名昭著的异常,也是最应该处理掉的异常,比如 空指针。
- 业务异常,并非由代码本身导致,而在不满足业务场景要求时手动抛出。
- 自定义类型的异常,通常属于业务异常。通常没有必要声明此类异常,且有可能带来一定的风险(二进制序列化场景下,序列化时有可能出现不识别自定义异常导致不能反序列化)。一旦声明和定义了自定义异常,就意味着一定会有独立的捕捉或与类型相关的处理方式,否则自定义类型的异常没有存在的意义(通常自定义类型的异常就是通过类型的识别完成独立捕捉或处理,鲜有人定义类型后为异常添加api)
§1.4 异常处理方式
- 不处理,直接抛出,通常出现在一个相对聚合的api或sdk中的较底层
- 继续抛出,先捕后抛,通常为了记录日志,复杂业务中比较有必要,因为需要留下足够信息量和辨识度的信息以供分析(否则有可能出现直接抛了异常后,当前服务没有留下任何痕迹的情况)
- 转换异常和隐藏,通常出现在分布式系统中,A服务调用了B服务,B底层出现异常,在服务层很可能捕捉异常,创建新异常(可能具有业务向的类型和msg以及统一错误码)抛出,目的是隐藏当前服务下异常细节(因作为调用方无需知道)
- 转返回。某些场景下不允许扔回一个异常,比如controller、open service等。可能导致跳转到错误页面而不是提示)
- 处理,这里指的有效的处理(上面的转换异常与转返回勉强也可归为此类)。通常有降级处理(查缓存的改查库),补偿逻辑(处理分布式事务回滚)等。
§1.5 异常处理思路
按 §1.4 中思路逐条判断
§2 日志异常常见场景处理方法汇总
1 特殊组件需要考虑添加触发日志(info/debug),本质是访问日志,但推荐使用业务日志形式记录
与业务、系统机制耦合度越高的组件越需要日志支持,反之倒是可以使用优先级很低的日志或者干脆通过遗传处理。当一个线上问题涉及到这些组件时,一个通用的排查思路是:有没有正常进入组件、组件是否工作正确、本次事务是否执行应该执行的逻辑支线,是否正常返回。而在这个过程中,组件的入口日志尤为重要
所谓特殊组件泛指mvc体系(controller/service/manager/dao 等)之外的自定义对象,常见(但不限于)listener,consummer,sender,scheduler,worker,helper,accessor 等等
对于极端重要的组件日志其实推荐使用error,不允许禁用。比如,当前系统是一个独立定时任务系统,定时任务的任务数据存在数据库中,每种任务对应一个topic。此系统的主要工作流程就是循环扫表,查到当前时间上触发的任务,生成消息,推送到对应topic中(再由各自系统监听执行),最后更新下次触发时间。若使用worker实现最主题的循环扫表,则每次循环的开始其实是至关重要的信息,相当于变种心跳。记录此信息,可以再出现问题时提供最保底的信息。所谓最基本的信息,比如每次具体是哪一毫秒触发的检查,窗口或分片信息是什么,检查的条件是什么等等。相对于庞大的业务日志,这些日志所占的比例很小,但一旦出现问题,很可能出现因为它们的确实导致无法开展有效的分析。这种时候,error级别的日志很有必要,当然,也可以使用比如info日志,同时确保项目的日志级别一定不再info之上。
有同学会怀疑这点功能需要一个独立系统吗?实际上,它都能做为一个独立的平台出现。怀疑的同学可以考虑一些周边功能。比如动态注册定时任务、注销定时任务、对接多个系统、对接多个mq、其他的任务执行调用方式、各种连接器等等。这里可以玩的东西还是很多的,甚至一套为所欲为的定时规则。
2 外部接口需要考虑添加日志,并在通常在获取返回后进行健壮性校验(info/debug+error)
外部接口(有可能需要接口提供方提供服务的接口)相对于当前服务而言通常属于重要步骤(都请人帮忙了能不重要吗),其响应通常影响后续逻辑,并且也没有太有效的排错手段(总不能有远程调试这样的功能吧),因此当调用外部接口时,理应使用日志。
一般的,外部接口正常返回,且返回值有效时,业务才能正常进行,因此理应添加健壮性校验。
未通过健壮性校验,且没有其他方式可以帮助后续业务正常执行(比如降级方案,其他的业务分支)的情况下,宜中断业务。中断时的常见操作包括但不限于日志,生成业务异常事件,触发运维性质逻辑(完善的系统甚至可以再此步骤自动收集信息生成运维任务,加入相关队列并在后面自动触发修复/重试逻辑),组织返回参数,抛出异常等。
3 流程化比较重的业务,建议添加流程节点日志(info/debug)
一些业务,就是流程性很强,换句话说步骤很多。比如,用户下了销售订单(参考,非实际业务):
- 检查处理缓存,检查当前单是否已经处理过(最终一致性)
- 如果有丢弃忽略,否则尝试上锁并设置超时时间
- 解析订单,生成标准订单数据(比如转换商品码,识别组套商品啥的)
- 获取订单明细,获取商品信息,获取商品数量
- 检查商品与对应可用库存,尝试进行预占库存操作
- 预占失败生成问题事件单等待后续处理,如果成功则记录订单信息
- 通知库房管理系统进行订单的生产
一种可能出现的场景是,一个try包括了上面所有步骤(但代码不见得很难看),或者若干步骤,其中异常均无特殊处理,即统一捕捉。
上面都是没有问题的,而问题在于,当出现异常时,如果异常提示信息并不足够独特,很容易不知道原始异常触发点或者不能直接业务已经处理到哪个步骤(分布式事务中会造成较大问题,因为涉及重试和补偿)。
因此,推荐使用流程节点日志,流程节点日志对复杂业务的系统联调作用极大。
在系统或机制型的代码中在较重要的逻辑节点也宜适度增加日志,可以看做是特殊的流程节点日志。这是调试和上线初期debug或监控的需要,但可以给一个较低的级别,以便功能稳定后关闭。
4 捕捉异常后基本上必加日志(error)
参考 §1.4 异常处理方式 ,捕捉后可以进行的操作如下:
- 记录信息,为当前系统留下信息,较少使用,只适用于不需要返回,异常也不影响功能或即时影响了并知道了信息也没有什么价值或没有有效处理手段的场景。应该可以通过其他方式查看操作是否成功或有效。
下图中,e/e.getMessage()的选择由是否需要栈追踪信息决定。
-
修改异常类型或信息后抛出
其意义通常在于将纯代码上的异常翻译成业务上的异常(换句话说,把异常的代码意义转变成业务意义),或说明下级业务异常导致了上级业务中哪个步骤执行不下去,越复杂的业务中越常用,且效果显著。
修改类型和信息的场景还出现在隐藏当前的异常信息,只提供外部应该知道的部分。比如服务a调用服务b,服务b出现了数据库异常,服务a有权利知道服务b挂了导致了自己的业务进行不下去,但服务b没有必要提供自己挂了的具体信息,而是转换成"xxx操作失败,请联系相关接口负责人" -
变更异常为返回值,适用于必须保证有效返回的场景,同时可以屏蔽不必要的信息
-
有效处理,包括降级等方式
5 业务中断的地方,需要记录日志,得让人知道怎么死的(error)
中断后,异常/返回可以根据具体业务决定
6 对处理bug或反馈项目运行中数据有效的信息,需要考虑日志,尤其是在生产环境中项目运行稳定之前(info/debug)
对于生产环境的项目,这类日志也有较大意义。业务的本质是一串有条理、有规律、有目的的对业务数据的操作,其直接产品忽略业务概念后,本质上都是数据。当业务本身足够复杂时,在几个关键操作节点可以通过日志看到正在被处理的数据本身,可以极大的降低问题成因分析的难度。因为这种日志,实质上可以起到一部分debug的效果,但需要注意,此类日志需要根据业务迭代即时调整。
有一种替代方案是提供一个查询接口,通过直接调用接口探知运行时数据,如下图,这当然是一种局限性较强不推荐普遍使用的方法
§3 业务日志写法推荐
日志的写法是否正确有效直接影响其作用大小,推荐一条日志中需要具备的要素有:
引 导 词 \color{red}{引导词} 引导词:用于说明这是哪里的日志,属于什么功能,一般是类名
定 位 词 \color{red}{定位词} 定位词:用于在范围内定位,推荐与引导词一起使用,否则容易造成定位不准或信息冗余。定位词比较灵活,可以是方法名,也可以是业务中某个自定义的步骤名,甚至就是日志文本,最终目的是帮助定位到一条日志,也可以在引导词中直接定位
b i z C o d e \color{red}{bizCode} bizCode:一般是业务主键或其他能区分同一处日志在不同请求中触发情况的字段,主要作用是区分前后几次不同的调用,只有当次调用的日志信息才是有帮助的,其他日志相对来讲都是噪音
信 息 段 \color{red}{信息段} 信息段:输出想在日志中体现的字段,可以有字段名也可以没有(其实我见过的最牛逼的日志正好就是没有的)
模 板 与 占 位 \color{red}{模板与占位} 模板与占位:日志和异常,推荐使用{}的方式进行占位,后面逗号拼接
示例:
整个黄框子是模板,{}是占位,后面按序填值
<<< 的作用:
用于精准的定位业务日志(尤其是在linux环境结合 grep 指令), 快速、精准的查找相关日志,任何带有<<<或>>>的是当前系统的业务日志,同时也用于隔离用于定位的信息和日志想表达的信息。
项目放到生产环境后,解决线上问题很有可能要求研发人员具备通过服务器上的日志文件快速排查bug的能力。通常的,此类作业的大体流程是:定位缺陷业务(有可能原始问题不是报错而是一个数据异常现象),定位日志信息,定位缺陷代码,分析具体bug原因,修改,验证。
通过 [cat 文件名|grep ‘’ -A n] 指令,可以快速查看一个文件中符合条件的内容及其后n行。此时,需要一个标记可以有效的筛除不是我们记录的日志的信息(比如框架自动打印的信息)以提高查找信息的精准度。此方式配合良好的日志,久经考验,屡试不爽。
私以为<是一个胖瘦适中,视觉清爽的符号。但,某些项目中,一些功能或者服务会使用xml作为报文格式,所以一层<不宜使用,二层与一层在视觉效果上区别不明显,因此选用使用<<<,相对简洁醒目。