日志的艺术(The art of logging)

 

正文python

 

  程序员学习每一门语言都是从打印“hello world”开始的,日志也是新手程序员学习、调试程序的一大利器。当项目上线以后,也会有各类各样的日志,好比记录用户的行为、服务器的状态、异常状况等等。打印日志彷佛是一件很简单、不值得一提的事情。可是,当看到线上项目竟然有这样的日志的时候,不由想问问咱们真的会打印日志吗?linux

***********************************程序员

Error Happened, F*ck编程

User xxx can not login  服务器

  在我看来,打印日志是一门艺术,并且长期被程序员所忽视,本文尝试回答如下几个问题,分享我对打印日志的一些思考:网络

  (1) why or when to logsession

  (2) what to log多线程

  (3) how to log and tips并发

  注意:本文中会用“打印"日志来统一表示日志的输出,但不是咱们狭义理解的输出到终端或者stdout、stderr, 而是泛指将日志内容输出到任何目标,包括但不限于终端、文件、网络传输。

  本文地址:http://www.cnblogs.com/xybaby/p/7954610.html 

why or when to log

  为何时候要打印日志,或者何时打印日志,在我看来是同一个问题,那就是打印日志的目的。不一样的目的,决定了日志内容的格式,输出的频度,输出的目的地。那可能有哪些打印日志的缘由?

  (1)调试开发

  目的是开发期调试程序使用,这种日志量比较大,且没有什么实质性的意义,只应该出如今开发期,而不该该在项目上线以后输出。如何控制这种类型的日志是否输出,后面也会详细讨论。

  (2)用户行为日志

  这种类型的日志,记录用户的操做行为,用于大数据分析,好比监控、风控、推荐等等。这种日志,通常是给其余团队分析使用,并且多是多个团队,所以通常会有必定的格式要求,开发者应该按照这个格式来记录,便于其余团队的使用。固然,要记录哪些行为、操做,通常也是约定好的,所以,开发者主要是执行的角色。

  (3)程序运行日志

  记录程序的运行情况,特别是非预期的行为、异常状况,这种日志,主要是给开发、维护人员使用。何时记录,记录什么内容,彻底取决于开发人员,开发者具备高度自主性。本文讨论的主要也是指这种类型的日志,由于做为一个服务端开发、运维人员,程序运行日志每每是解决线上问题的救命稻草。

  (4)记录系统或者机器的状态

  好比网络请求、系统CPU、内存、IO使用状况等等,这种日志主要是给运维人员使用,生成各类更直观的展示形式,在系统出问题的时候报警。

 

what to log

  一条日志要包含哪些内容,我觉的应该包含 when、where、how、what、who、context,具体含义会在下面一个小节介绍。

  咱们要记录日志,老是要在某个时机,好比用户的某个请求、某个网络调用、或者内部状态发生了改变。在后文中,统称为事件(event),即日志内容是对某个事件的描述。

when: the time event happens

  when,就是咱们打印日志的时间(时间戳),注意这里的时间指的是日志记录的事件的发生时间,而不是日志被最终输出的时间。好比若是日志的输出目标是文件,那么这里的when不是写入到文件的时间,由于每每有延迟。

   时间的重要性,在《Distributed systems for fun and profit》中有很好的讲述。

  首先,时间能够被解读(Interpretaion)成具体的、现实的日期,让咱们能够知道事件发生时的时间环境,好比出问题的时候是否是有什么活动、结合系统日志分析当时服务器的网络、CPU、IO是怎么样。具体的时间点也能够帮助咱们分析事件的发生是否是存在某种规律,好比是否是天天、每周、每个月的固定时间点都会出问题。

  其次,时间能够表示一个(一组)事件的持续时间(duration)。好比,能够监控处一段代码的执行时间,也能够记录一个网络请求的耗时。这个时间差也能给出咱们不少信息,好比根据经验预判当时程序的运行状态,是否比较‘卡’。

  最后,时间表明了事件发生的顺序(order),咱们将多个日志按照时间排序,这个顺序能帮助咱们debug到底问题是怎么产生的,是按照什么样的时序。这对于多进程(多线程)、异步、分布式程序而言很是重要。虽然咱们知道在分布式系统维护全局的时间(global clock)是很复杂的一件事情,但咱们使用NTP协议,基本上能解决大部分的问题。

where: where the event happens

  where,就是指日志是在哪里的被记录的,本质上来讲,是事件的产生地点。根据状况,能够具体到是哪一个模块、哪一个文件,甚至是哪个函数、哪一行代码。实践告知,至少应该包含模块信息。

  where的意义在于可以让本身或者其余程序员一眼就看出这条日志是在哪里产生的,这样就能大体定位问题处在哪里,而不用从日志内容全局grep代码

how:how importance of the event

  how important,表明了事件的重要性,咱们会打印不少各类类型的日志,可是不一样的日志的重要性是不同的。好比,调试日志是最不重要的,是不该该出如今线上项目的,可是程序运行报错日志却须要认真对待,由于表明程序已经出现了异常。即便是程序的报错日志,也有不一样的紧急程度,一次网络请求超时跟子进程异常退出分量彻底不同。

  所以,每一条日志都应该有log level,log level表明了日志的重要性、紧急程度。不一样的语言、框架的level细分有必定的差别,但都会包括debug,info,warn,error,fatal(critical)。其重要程度从名字就能够看出。

  固然,有时候,warn与error,或者error与fatal之间的界限不那么明显,这个须要在团队之间达成共识。在咱们的线上项目,对于error、fatal级别的日志都会报警,若是出现了error日志,那么最迟须要次日去处理,若是是fatal日志,即便是在大半夜,也得马上起来分析、处理。

what:what is the log message

   what是日志的主体内容,应该简明扼要的描述发生的什么事情。要求能够经过日志自己,而不是从新阅读产生日志的代码,来大体搞清楚发生了什么事情。因此,下面这个日志是不合格的:

1 def user_login(username, password):
2     if not valid_username(username):
3         logger.warn('Error Happened')
4         return
5     # some others code

  是的,我知道,出了问题了,可是日志应该告诉我出了什么问题,因此日志至少应该是这样的:

1 def user_login(username, password):
2     if not valid_username(username):
3         logger.warn('user_login failed due to unvalid_username')
4         return
5     # some others code

 

who:the uniq identify

  who表明了事件产生者的惟一标识(identity),用于区分一样的事件。特别是在服务器端,都是大量用户、请求的并发,若是日志内容不包含惟一标识信息,那么这条日志就会淹没在茫茫大海中,好比下面这条日志:

1 def user_login(username, password):
2     # some code has check the username
3     if not valid_password(password) or not check_password(username, password):
4         logger.warn('user_login failed due to password')
5         return
6     # some others code

 

  上面的代码给出了出了什么问题,可是没有包含是谁出了问题,至少应该是

def user_login(username, password):
    # some code has check the username
    if not valid_password(password) or not check_password(username, password):
        logger.warn('user_login failed due to password, username %s', username)
        return

  日志的惟一标识也能帮助咱们检索、过滤,找出该惟一标识的最近一段时间的全部日志,再按照时间排序,就能还原日志主体的活动轨迹,好比一个用户在网站上的操做会发散到多个进程、服务。当经过用户名(用户的惟一标识)搜索日志时,就能还原该玩家的操做记录,这个在查线上问题的时候很是有效。

  固然,这个惟一标识是很普遍的,须要根据具体状况决定,若是网络请求,可能更好的是requestid、sessionid;若是是系统日志,那么多是进程、线程ID;若是是分布式集群,那么多是副本的惟一id

context: environment when event happens

  日志记录的事件发生的上下文环境直观重要,能告知事件是在什么样的状况发生的。固然,上面提到的when、where、who都属于上下文,这些都是固定的,通用的。而在本小节,context专指高度依赖于具体的日志内容的信息,这些信息,是用于定位问题的具体缘由。好比

1 def user_login(username, password):
2     # some code has check the username
3     if not valid_password(password) or not check_password(username, password):
4         logger.warn('user_login failed due to password, username %s', username)
5         return
6     # some others code

 

   阅读代码,当password不符合规范,或者校验password失败的时候都会出错,可是究竟是那种状况呢,日志内容并无指出,因此这条日志仍然不合格。

  在我看来,这部分是弹性最大,可是又最重要的部分,形成异常的状况不少,记录哪些信息,彻底取决于写代码的程序员。但事实上也很简单,遵循一个原则便可:想一想加上哪些信息能定位问题发生的缘由

how to log and tips

use logging framework

  早期的编程语言提供的日志功能都比较初级,通常都是输出到终端或者文件,如C++、Java,并且不支持统一的输出格式的配置。对于这些语言,通常会有单独的log框架,如glog,log4cpp,log4j,elf4j等等。而更新的一些语言,通常都内置强大的logging模块,如python。

  在前面在讲述“what to log”的时候,咱们指出要记录日志发生的时间、地点、等级等信息。那么这些信息是否是每次都在日志内容里面打印呢,这些内容确实是一条完整的日志所必须的,可是若是要程序员写每条日志的时候都得手动加上这些内容,那么无疑是一种负担。框架、模块的做用就是将程序员从这些繁文缛节中解放出来。好比在不少logging框架模块(thon logging、log4j)中,都有named logger这一律念,这个name就能够是module, filename, classname或者instance,这就解决了上一章节提到了“where the event happen”这个问题。

  在这里,对logging框架的介绍就不详细展开,只是总结一下logging框架、模块的功能

  (1)设置log的输出等级

  这样能够不改程序代码,仅仅修改log的输出等级,就可以控制哪些日志输出,哪些日志不输出。好比咱们在开发期的调试日志,均可以设置为DEBUG,上线的时候设置输出等级为INFO,那么这些调试日志就不会被输出。

  (2)设置每条日志默认包含的内容

  以Python logging为例,能够经过formatter设置每条日志默认包含哪些信息,好比时间、文件、行号、进程、线程信息。

  (3)设置日志的输出目标

  经过配置,能够指定日志是输出到stdout,仍是文件,仍是网络。特别是在linux服务器上,将日志输出到syslog,再使用syslog强大的处理、分发功能,配合elk系统进行分析,是不少应用程序的通用作法。

log never throw

  咱们打印日志,是为了记录事故发生的现场,以便发现问题,解决问题。那么就得保证,打印日志这一行为自己不能引入新的问题,好比,不能出错抛异常。这就比如,处理车祸的消防车不能冲进现场同样。

  可是,越重要的日志,好比Error、 Fatal级别的日志,出现的几率应该是越低的,咱们也不但愿产生这样的日志,由于一旦出现就意味着异常或者线上事故。这样的日志,就必定要作好单元测试、覆盖率测试,保证日志自己是可以正常工做的。

log when u think something never happen

  这一点,应该是针对why or when to log而言。就是说,当你认为某种状况必定不会发生,按照墨菲定律,它仍是极可能会发生,那么就应该在万一发生的状况记录log,Error(Fatal)级别的log。尤为是在异步,并发的状况下,程序员任务的不可能都会成为可能。

  好比下面的伪代码

1 def magic_func():
2     if check_ok():
3         do_something()
4 
5     return

 

  代码很简单,若是条件知足,那么就作相应处理,不然直接返回。这里有两种可能,第一种是条件不知足是可能的、可预期的状况,只是说,在这种状况下什么都不用做;第二种状况是程序员以为条件必定会知足,必定不会出现else的状况,因此什么都没作。若是是第二种状况,那么就必定得加日志,由于一切均可能发生。

lazy logging

  日志的内容,在最终输出的时候,应该是一个字符串,那么这个字符串是何时产生呢?前面提到,咱们能够经过log level来控制一条日志是否被输出,那么字符串的生成越迟越好,由于有可能日志根本就无需输出,也就无需生成这个字符串,这也是我以前提到过的lazy思想

  至于lazy logging,各个语言、框架都是大同小异的,在这篇文章中,举出了log4j的例子,在这里仍是用我比较熟悉的python讲解这个例子

复制代码
 1 #coding=utf-8
 2 import logging
 3 
 4 logger = logging.getLogger('LazyLogging')
 5 logger.setLevel(logging.DEBUG)
 6 hander = logging.StreamHandler()
 7 formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s') 
 8 hander.setFormatter(formatter)  
 9 logger.addHandler(hander)
10 
11 def getUserCount():
12     logger.info('getUserCount is called')
13     return 1
14 
15 logger.debug("There are " + str(getUserCount()) + " users logged in now.")
复制代码

 

  上面的代码可谓麻雀虽小五脏俱全,包含了使用logging框架的方方面面。第4行是named logger,第5行设置log level,第6行指定输出目标,第7行指定输出格式(包括时间,logger name,log level,具体的日志内容)。

  运行结果以下:

2017-12-02 17:52:20,049 - LazyLogging - DEBUG - getUserCount is called
2017-12-02 17:52:20,049 - LazyLogging - INFO - There are 1 users logged in now.

  因为当前的log level是DEBUG,那么第15行的日志会输出,这是正常的。

  可是将log level改为INFO,“getUserCount is called”这条日志仍然会被输出。这就暴露出两个问题,第一,即便日志内容最终不会被输出,仍然会生成一个字符串;第二,必定会调用getUserCount 这个函数,而若是根据log lebel不须要输出日志,这两步都是没有必要的

  要解决第一个问题很简单,将第15行改为

logger.debug("There are %s users logged in now.", getUserCount()) 

  便可,可是“getUserCount is called”这条日志仍然会被输出,即第二个问题仍然没有解决

  按照stackoverflow上的这篇文章,也是能够解决第二个问题的,方案以下

复制代码
1 class lazyEval:
2     def __init__(self, f, *args):
3         self.func = f
4         self.args = args
5 
6     def __str__(self):
7         return str(self.func(*self.args))
8 
9 logger.debug("There are %s users logged in now.", lazyEval(getUserCount))
复制代码

 

  在log lever为INFO的时候,能够发现“getUserCount is called”也不会被输出了,即不会调用getUserCount函数,作到了真正的lazy logging。

  可是,这是很是很差的写法!除非大家保证所调用的函数是没有反作用的(side-effect),即函数的调用无状态,不会改变程序的状态,不然程序的状态竟然会依赖于log level,这是一个陷阱,一个坑,一点都不pythonic。

consider async logging

  日志的记录也是要消耗时间的,这也是咱们不能处处打印日志的缘由。通常来讲,logging框架的效率都是比较高的,可是若是profile发现日志的输出确实带来了不容忽视的消耗,那么也是值得优化的,其中的一个方法就是异步log,以免日志输出阻塞线程

conclusion

  在网上看到这么一句话

Logs are like car insurance. Nobody wants to pay for it, but when something goes wrong everyone wants the best available  

  log就像车辆保险,没人愿意为保险付钱,可是一旦出了问题谁都又想有保险可用。

  咱们打印日志的时候都很随意,因而在差bug的时候,就会骂别人、或者几天前的本身:SB!

  从今天起,写好每一条日志吧,与君共勉!

references

Distributed systems for fun and profit

python logging#logrecord-attributes

the-art-of-logging-advanced-message-formatting

 

 

出处:http://www.cnblogs.com/xybaby/p/7954610.html

相关文章
相关标签/搜索