前言

想要设计并完成一个靠谱的系统,不可或缺又常常被很多码农嗤之以鼻的有这么几个方面:

1.程序日志、日志系统

2.系统监控、阈值报警

3.单元测试、接口测试、系统测试、e2e测试等等

4.服务trace、调用链条跟踪  

但实际上这四方面对于一个工程来讲都非常的重要。本文先对日志方面的问题进行一些探讨。

如何debug?

对于一个系统来讲,在开发阶段,你可以通过各种手段来进行debug。其实常用的手段也没多少,大致就是,借助输出/打印信息单步调试记录日志

先说集中输出流。具体到前后端上,各自有自己的途径。比如打印信息,前端可以直接alert,或者可以对用户无骚扰的console.log(在node里也可以用),然后在控制台里去查看记录。而后端的话又会根据语言稍微有一些区别,比如php里,可以直接var_dump/print_r/echo,随便你怎么用。如果是在java里,那你可以System.out.println,换golang,你也可以用fmt包里的fmt.Print*任意一个函数,等等。总结一下,就是在你看得到的地方把内容打出来,不管是标准输出流,还是页面,抑或是别的什么东西。这些信息可以帮助你一步一步地进行开发。debug的时候打印信息也有一些技巧,刚入行的同学可能有时候会遇到一种问题,突然接手了一个bugfix工作,但这个模块有5000行代码,函数都很长,看都看晕了,怎么debug?这种时候就是分治大显神通的时候了,你可以不用动脑子,直接在函数正中央插入一条print,然后查看bug出现在print之前还是在之后(在之前的话很可能print就出不来了嘛),然后再根据位置再次进行分治。这样你的bug再难找,迟早还是能找得到在哪里的。

然后是单步调试,这个又是个根据语言不同而不同的问题。如果是C或者C艹,那基本上没有比gdb好用的东西(在linux平台下)。如果是php,那需要自己去下一个xdebug。如果是java,现在所有的java IDE都提供了方便的单步调试功能。golang也有类似delve这样的调试工具,而且也可以直接用gdb对其进行调试。

但实际上两种方式都存在一些问题。因为直到debug的时机你才会想要去打印什么的话,一般也就意味着你的应用本身记录的日志信息就不太完善(偶发的bug除外)。单步调试的话也同样,你需要做一些问题的假设才好去设置断点。设置断点的时候还需要小心翼翼地尽量绕过一些很大的循环(否则可能定位问题之前点鼠标或者按键都累死了)。

对于一个web应用来讲,其业务逻辑都很简单(毕竟都是CRUD和ifelse)。完备的应用应该是可以直接通过日志来排查出大部分的bug。如果是逻辑复杂,switch分支多的,那就更应该记录日志了,这样你在某一种情况出现的时候,可以迅速地根据日志去重建bug发生时刻的完整场景(你也可以理解成那个时刻的函数调用栈和所有的变量信息),并且可以按照场景准确地给其它人描述发生了什么事情导致了这样的问题,或许可能都不是程序的问题。但如果你说不清楚发生了什么事情,就会有很大的机率去让你背锅了。

例如我们在开发阶段的类BI的数据中心,有很多时候,会有人突然跑过来问你,为什么这里这条数据和其它数据源或者计算方法得出的不一样?这种时候,如果你没有线上的sql日志,真的是要直接懵逼了。之前我的日志被删除的一段时间里,排查这种问题只能去把日志加回来,然后重新进行一次上线,再次完成一遍完整的请求,才能够知道为什么这里的数据是这个样子,而不是提问者的那个样子。而这些问题其实大部分都是和程序本身没什么毛关系的问题。但是为了帮他们解决这些问题,我被消耗掉了大量的无意义的时间。

实际上很多人会觉得打日志这种方式不太好。例如我司的实际开发过程中,我发现很多大公司出来的人,例如百度/阿里的人都对把日志打全这种事情比较排斥,他们给出的理由是,如果日志打得多,那么线上的日志文件膨胀就会非常地快,这样可能很快就触发线上机器的磁盘报警了。

但不是所有的公司的业务都会像百度或者阿里的量级的。就算你真的每一行都打上日志,按照我们的系统的qps,一天的日志撑死也就几个G。这里有人要说我这是胡搅蛮缠了,那么我们用数据来说话,假设一条日志平均1KB(其实1KB已经不小了)。按照我们这种QPS可能连两位数都不到的系统来说,每天可能也就800000左右的请求,每一个请求如果我产生10条日志的话,那么就是800w条日志,实际上也就8GB。你的硬盘都有1.4TB呢,用得着吝惜这一点空间么,只要过几个星期去清理掉无用的历史日志就好了啊。

而且在系统没有稳定下来的时候,哪里来的那么多用户啊,请不要着急把所有的日志都删掉。

当然在某些情境下,他们说的也有道理,QPS都不过两位数的系统的情况下,打全日志是没问题,但如果QPS几百甚至上千的情况下,一天产生的日志量就非常可观了。但这也要分情况,如果真的QPS到四位数的话,不可能只有一台业务机器的。

但请求量大了以后日志量膨胀也确实是一个问题,这个问题怎么解决呢?

答案就是对日志进行分级。

先看一个比较常见的分级模式,来自于golang的日志库logrus(别跟我说标准库的log,那是渣渣):

Debug  
Info  
Warning  
Error  
Fatal  
Panic  

除了Panic可能和golang语言有些具体的相关性外,剩下的几个level和其它语言其实差不多。再具体到名称上,可能在其它语言/库里有叫什么Notice之类的level,和Warning意思好像差不多,但又好像不太一样,反而没那么直观了。

如果没有自己在程序里加过日志的,一看到这么多日志级别直接就懵了。但实际上上面的日志级别从上到下,本质上没有什么区别。不同级别的日志只是为了让你在查看日志的时候一眼对其进行区分。另外,如果你有专门的日志存储,那么可能会针对不同级别的日志进行一些查询(其实大多数情况下还是关注Error级别的log更多)。

为日志加上了这么多等级以后,我们还需要在程序里加一些开关来使我们的程序可以随时控制程序运行时的日志级别。一般情况下,线上的程序至少要设置为Info级别以上。较为稳定的程序--你也还是把Info开开吧,除非你想在出了什么问题的时候让自己无迹可查。

至于Debug级别的日志,那就要尽量打得细致一些了。比如从请求到达服务,输入参数是什么,每一个参数值是什么,参数在流转过程中发生了什么变化,用于定位到整个请求链的uuid/traceid,调用过程中在每一步都用了多久,使用的线程(goroutine)id,运行时程序整体的状态,等等。

不管什么级别的日志,都需要带上你的模块名和函数名,实际上可以的话,最好连文件名和行号都能带上。这里可以先来看看java的Logger工具打出来的一些样例:

18:16:15,233 [main] [WARN] k.u.VerifiableProperties - Property topic is not valid  
18:16:21,531 [main] [WARN] o.s.w.c.s.XmlWebApplicationContext - Exception encountered during context initialization - cancelling refresh attempt  
org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'jazzStartSpringListener': Injection of autowired dependencies failed; nested exception is org.springframework.beans.factory.BeanCreationException: Could not autowire field: private com.xiaoju.kefu.jazz.web.kafka.optimus.OptimusPublicLogKafkaHandler com.xiaoju.kefu.jazz.web.listener.JazzStartSpringListener.optimusPublicLogkafkaHandler; nested exception is org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'optimusPublicLogKafkaHandler' defined in file [/Users/Xargin/git/jazz-parent/jazz-web/target/classes/com/xiaoju/kefu/jazz/web/kafka/optimus/OptimusPublicLogKafkaHandler.class]: Instantiation of bean failed; nested exception is org.springframework.beans.BeanInstantiationException: Could not instantiate bean class [com.xiaoju.kefu.jazz.web.kafka.optimus.OptimusPublicLogKafkaHandler]: Constructor threw exception; nested exception is org.I0Itec.zkclient.exception.ZkTimeoutException: Unable to connect to zookeeper server within timeout: 6000

实际上。。我觉得java的日志打得有点太啰嗦了,应该能有一些更好的简化日志的方式,不过我也不是很懂java,要是谁了解的话可以给我介绍更好的日志库~

不过从上面也可以看到一些日志里应该要有的元素了,如果你要自行设计一个日志模块,输出方面是可以对java的日志进行参考的。这方面我觉得golang的这些日志库就做得不是很好,当然,也可能是我不太了解。之后理解深入可能会做一些订正。

别说php了,php自带的日志系统太弱了。

如何设计一个靠谱的logutil

前面从如何debug一直引申到靠谱的日志输出。那么要怎么设计一个靠谱的日志库呢?我觉得大概要考虑下面一些方面:

1.api要足够简单

2.支持分级别日志

3.支持多种方便的格式输出

4.默认携带的信息应该全面,并且可以配置

5.根据语言不同而不同的其它考虑  

第一点很简单,比如logrus,每种级别的api都有xxxf和xxxln两种打印方式,而且也就这么两种。

支持分级别这个也简单,实际上就是对应级别的日志在输出的日志条目中要带上对应的标记,具体的有可能[Warn]这种形式的,像etcd的日志就比较有意思,他们只用一个字母来代表日志的级别。但其实我觉得这种日志可能需要grep查询的时候不太方便。可能还得借助一下awk,倒也不难。

第三点和第一点意思差不多。

第四点这个可能就没法一概而论了,根据语言不同而不同,毕竟你在php里要获取文件可以直接__FILE__,获取行号可以__LINE__。但在java里就要getClass().getName()这样。到了golang里可能又要换一种写法,可能变的没那么容易了。目前做的比较好的日志库都会默认要求你以某种方式提供模块/类名,至少可以在运行期间可以看得到是哪个模块的问题。

第五点就留给你去思考了。

除了上面这些点之外,在php这种转瞬即释的脚本语言和能够常驻内存的语言中,实际上日志刷磁盘的具体实现方式可能也会稍微有一些区别。比如在php里,所有的操作都是同步的,这时候你几乎没有办法异步地去做写文件这件事情,所以写日志的操作也是同步的。这时候唯一要考虑的就是可能有多个php进程在写同一个文件,所以一般php的日志模块实现也都比较简单,只是在写文件之前简单的flock,在写完之后unlock。

如果是常驻内存型的语言,写日志可以用更高明一些的方式。比如你可以让写日志这件事情变成一个异步操作,可以在内存里有专门的队列来刷磁盘,这样你的写文件操作不会阻塞你的业务。虽然丢日志的可能性也有,但显然这样做效率更高一些。如果你的日志量比较大,批量刷磁盘显然是最好的方式了。

如何使用/设计一个靠谱的日志系统

现在日志系统的可用解决方案实际上也比较多,比如很流行的elk、flume等等。

elk是指elasticsearch/logstash/kibana三大套件,这个在很多公司都有应用了。当然es这么强大,只做日志系统的搜索功能稍微有点屈才了。你看我们不就拿他来做工单的查询嘛。

在elk这套系统中,logstash是日志的输入端,你可以在logstash里配置一些日志的采集规则,然后通过redis/kafka或者直接让这些日志流向es这个后端的存储。

在采集到对应的日志之后,便可以在kibana里进行一些查询和图表展示了。

之所以需要一套集中的日志系统,是因为现在大多数的大型系统都是分布式系统,一次用户请求可能真的就会流经几十台机器,如果你不把日志集中起来进行存放和查询,那做分析和排查问题可真要累死了。。

以上。实际上现阶段我对日志系统本身了解也不是很多,如果日后了解深一些的话,展开再讲。