麦子学院 2017-02-25 10:35

Flask学习之日志详解

回复:0 查看:2849

我们在开发基于Flask 的 Web 应用时，往往容易忽略了对日志的使用，而在 Flask 的官方文档中，对日志这块的介绍也仅仅停留在如何与系统集成上。记录日志这个看似很简单的事情，在实际中很多人却不一定能做好，要么不知道何时进行日志记录，要么就是记录的日志然并卵。所以，今天就来说说记录日志这件小事，希望对大家学习flask有所帮助。

　　说它是件小事，因为它的确不会影响你系统的正常流程，有没有它系统都能跑起来，也正因为这样，很多人便忽略了日志的处理，或者干脆都没有配置日志输出，整个系统没有任何日志输出（Nginx 日志不算）。当然，如果是我们自己开发的一些小网站，大家用来练练手或着用户量不大，有没有日志都一样，但是对于一些大型的系统，它的用户是很多的，在任何一个环节都可能出问题，为了能够及时的定位问题和监控系统运行状态，正确合理的记录日志就非常非常重要了。一般情况下，我们需要关注的是三个方面的内容：

　　· 日志信息的集中采集、存储和检索：这个主要是在多节点的情况下如何方便的查看日志信息。

　　· 日志信息的输出策略：要保证日志输出的全面而又不显凌乱，方便开发人员跟踪和分析问题。

　　· 关键业务的日志输出：我们常说的打点就属于这个范畴，比如我们的一些浏览记录等，这个就需要根据业务要求来做针对性设计了。

　　我们在这里主要是围绕第二个问题来展开，也是我们开发人员最直接接触的情况。

　　日志输出级别

　　从Flask 0.3 版本开始，系统就已经帮我们预配置了一个 logger ，而这个 logger 的使用也是非常简单：

　　app.logger.debug('A value for debugging')app.logger.warning('A warning occurred (%d apples)', 42)app.logger.error('An error occurred')

　　其中的app 就是 Flask 的实例，而这个 app.logger 也就是一个标准的 logging Logger ，因此，我们在使用 app.logger 时可选择的输出级别与 python logging 中的定义是一致的。

　　· ERROR ：这个级别的日志意味着系统中发生了非常严重的问题，必须有人马上处理，比如数据库不可用了，系统的关键业务流程走不下去了等等。很多人在实际开发的时候，不会去区分问题的重要程度，只要有问题就error 记录下来，其实这样是非常不负责任的，因为对于成熟的系统，都会有一套完整的报错机制，那这个错误信息什么时候需要发出来，很多都是依据单位时间内 error 日志的数量来确定的。因此如果我们不分轻重缓急，一律 error 对待，就会徒增报错的频率，久而久之，我们的救火队员对错误警报就不会那么在意，这个警报也就失去了原始的意义。

　　· WARN ：发生这个级别的问题时，处理过程可以继续，但必须要对这个问题给予额外的关注。假设我们现在有一个系统，希望用户每一个月更换一次密码，而到期后，如果用户没有更新密码我们还要让用户可以继续登录，这种情况下，我们在记录日志时就需要使用WARN 级别了，也就是允许这种情况存在，但必须及时做跟踪检查。

　　· INFO ：这个级别的日志我们用的也是比较多，它一般的使用场景是重要的业务处理已经结束，我们通过这些INFO 级别的日志信息，可以很快的了解应用正在做什么。我们以在 12306 上买火车票为例，对每一张票对应一个 INFO 信息描述 “[who] booked ticket from [where] to [where]” 。

　　· DEBUG 和 TRACE ：我们把这两个级别放在一起说，是应为这两个级别的日志是只限于开发人员使用的，用来在开发过程中进行调试，但是其实我们有时候很难将DEBUG 和 TRACE 区分开来，一般情况下，我们使用 DEBUG 足以。

　　以上就是我们实际开发中最多接触的几种日志级别，基本能覆盖99% 的情况。最后我们要注意的就是，最好能尽可能输出更多的日志信息，并且不做任何过滤，同时输出的每一条日志的详细信息要切当，让我们可以快速过滤并找到所需的信息。

　　日志输出信息

　　当我们确定了使用哪个级别来写入日志后，下一步要做的就是确定要记录什么样的信息。针对这一块的内容，其实又可以细分。

　　日志应该记录什么

　　一般来说，日志的记录要满足几个要求：可读、干净、详细和自描述。我们先来看几个反模式的例子：

　　app.logger.debug('message processed')

　　app.logger.debug(message.get_message_id())

　　app.logger.debug('message with id %s', message.get_message_id())

　　if isinstance(message, TextMessage):

　　...else:

　　app.logger.warn('unknow message type')

　　上面列出的这几个例子，问题在什么地方呢？当看到这些日志信息后，我们首先意识到的肯定是哪里出了问题，但是，这个问题产生的原因是什么我们并不清楚，也就是说，只根据这样的日志我们是没办法对问题进行修复的。所以我们在记录日志的时候，应该要尽量的详细，日志的上下文要交代清楚。

　　另外一种反模式的日志信息，我们通常叫做魔法日志。就比如说，有的开发人员为了自己查找信息方便，会输出一些类似&&&###>>>>>> 的日志，这些特殊的符号只有开发者本人清楚到底是做什么的，而对其他人来说，看到这些日志绝对是一脸懵逼。即使是开发者本人，哪怕当时能够清楚这些魔法日志的特殊含义，但时间一长，估计他们也很难回想起当时为啥要输出这些鬼东西了吧。

　　其次，还有一种是要关注外部系统，也就是在和任何外部系统通信的时候，建议记录所有进出系统的数据。但是，记录这些信息时，性能是一个比较头痛的问题，有时，需要和外部系统交换的信息量太大，导致无法记录所有信息。但是，在调试或测试期间我们还是愿意记录所有信息，并准备为此付出一些性能的代价，这个可以通过仔细控制log 级别来实现，比如：

　　if app.config['debug']:

　　app.logger.debug('...')else:

　　app.logger.info('...')

　　最后要提的一点就是，我们输出的这些日志信息中，绝对不可以透露系统密码和一些个人信息。

　　如何打印日志内容

　　当我们明确了该用哪个级别去记录哪些信息后，就要把这些信息输出到日志文件中，但是想正确高效的打印日志内容也并非一件简单的事。Flask 已经帮我们预配置了一个 logger ，我们可以使用这个 logger 来完成我们所有的打印操作。

　　我们在记录日志的时候绝对不可以使用 print ，即使我们在开发调试的时候能够在控制台看到打印的信息，但是这样的信息并不会记录到日志文件中，当我们的程序上线后，跟没有记录日志的效果是一样的。因此，哪怕是在开发调试时，也要尽量使用logger 。

　　最简单的日志打印就是输出一个字符串，比如像下面这样

　　app.logger.info('this is a string')

　　但大部分时候，我们要记录的信息都会包含一些参数，有一种实现方式是提前构造出这个字符串

　　message_info = 'the message is %s' % info

　　app.logger.info(message_info)

　　这种写法也没啥问题，但其实，logger 内部也可以帮助我们完成上面的操作，也就是我们还可以写成下面这样

　　app.logger.info('the message if %s', info)

　　这样看起来是不是简洁了好多呢？

　　记录异常信息

　　记录异常信息严格来说也应该算到日志输出的范畴，之所以把它拿出来单独说，是因为除了说明应该怎样去记录异常外，这里还要说下如何去自定义异常。

　　正确的记录异常信息

　　对于异常，我们更想看到的其实是它的堆栈信息，而不是简单的一句话，堆栈信息可以帮助我们快速的定位问题出处。如果想打印堆栈，我们前面的记录方法就不再实用了，哪怕我们把 Exception 的实例丢到logger 里打印出来的也仅仅是错误信息而不是堆栈信息。比如下面的例子

　　a = [1, 2, 3]try:

　　print a[3]except Exception, e:

　　logging.error(e)

　　如果我们查看日志，发现打印出的仅仅是一行错误信息：

　　Tue, 24 Jan 2017 16:07:20 demo.py[line:22] ERROR list index out of range

　　那如何打印出堆栈信息呢？python 给我们提供了一个 exception 方法，它的使用跟 debug 、info 、 warn 、 error 几个方法是一样的，我们可以把上面的代码修改一下

　　a = [1, 2, 3]try:

　　print a[3]

　　except Exception, e:

　　logging.exception(e)

　　之后我们再看日志输出

　　Tue, 24 Jan 2017 17:19:37 demo.py[line:22] ERROR list index out of range

　　Traceback (most recent call last):

　　File "/Users/xiaoz/developments/python/ttest/demo.py", line 20, in test

　　print a[3]

　　IndexError: list index out of range

　　除了我们上面使用 error 方法打印的错误信息外，还打印出了出错的堆栈信息，由此看见， exception 方法打印的日志会包含两项，第一项就是调用exception 方法时传入的message ，还有一项是紧跟在 message 后面的堆栈信息。

　　当我们使用 exception 方法时，它记录的日志级别为 ERROR ，如果我们希望打印出堆栈信息，同时又不希望使用 ERROR 这个级别怎么办呢？如果你查看exception 方法的实现，会发现，它只是多加了一行代码 kwargs['exc_info'] = 1 ，然后调用了 error 方法，以此类推，如果我们希望打印堆栈信息就可以像下面这样写： app.logger.info('message info is %s', message, exc_info=1) 。

　　Flask 允许我们自定义对异常的处理，一般情况下，我们会做一些统一处理，比如下面这样

　　@app.errorhandler(500)def internal_server_error(e):

　　app.logger.exception('error 500: %s', e)

　　response = json_error('internal server error')

　　response.status_code = 500

　　return response

　　我们在返回结果的同时，对错误信息进行了记录，这样做也是为了避免模板代码，减少开发人员的工作量。但是，在减少我们开发量的同时，这也意味着可能会带来另外一个问题，很多程序员喜欢捕获异常后将错误写入日志，然后再将异常包装后重新抛出，这样会重复打印日志信息：

　　... some thing ...

　　try:

　　... do some thing ...except Exception, e:

　　app.logger.error(e)

　　raise SomeException(e)

　　还有一种情况，如果我们在捕获异常的时候，不分情况统一捕获 Exception 也是不对的。直接捕获 Exception 固然方便，但是我们捕获的范围太大的话，有的时候会吃掉关键的信息，而这些被吃掉的异常又没有打印错误信息和堆栈，一旦有问题，是很难排查的，比如我们定义了下面的方法

　　def some_method():

　　.. do some thing ..

　　try:

　　.. do dome thing 2 ..

　　return True

　　except Exception, e:

　　return False

　　当 do some thing 2 中发生异常时，我们是没法察觉到的，这样不但会使方法返回不正确，也会给排查带来困难。

　　自定义异常

　　首先，我们看看为什么要自定义异常，在需要抛出异常的地方，我们直接 raise Exception() 不好吗？答案很显然，肯定是不好，具体的原因，我们下面就逐条分析下。

　　1. 大多时候我们都是使用 json 来为不同端提供接口支持，不管成功与否，都必须使用统一的数据格式。如果系统充斥着各种异常就很难做到统一。

　　2. 要能反映出该异常的重要程度，比如：如果是参数校验异常则被认为不是很重要，可能直接记下 warn 日志就行了，而 orm 异常必须要记录 error 日志。

　　3. 最后，对于异常的信息要有区分，比如，对于 orm 异常，我们希望给用户看到的是一条简单的系统出错的提示信息，而我们在查看日志时必须要有详细的异常信息。

　　为了解决上面的问题，需要我们来自定义异常，并且使用的时候也尽量要使用已定义的异常类。这里我们来看一种实现方式，大家可以参考

　　class BaseError(Exception):

　　default_status_code = 200

　　LEVEL_DEBUG = 0

　　LEVEL_INFO = 1

　　LEVEL_WARN = 2

　　LEVEL_ERROR = 3

　　def __init__(self, message, status_code=None, extras=None, parent_error=None):

　　self._message = message

　　self._code = status_code

　　self.extras = extras

　　self.parent_error = parent_error

　　self.level = BaseError.LEVEL_DEBUG

　　@property

　　def status_code(self):

　　if not self._code:

　　return BaseError.default_status_code

　　return self._code

　　def to_dict(self):

　　rv = {

　　'error_message': self._message,

　　'status_code': self.status_code,

　　'success': False

　　}

　　return rv

　　class ValidationError(BaseError):

　　def __init__(self, message, extras=None):

　　super(ValidationError, self).__init__(message=message, extras=extras)

　　self.level = BaseError.LEVEL_INFO

　　class NotFoundError(BaseError):

　　def __init__(self, message, extras=None):

　　super(NotFoundError, self).__init__(message=message, extras=extras)

　　self.level = BaseError.LEVEL_WARN

　　class FormError(BaseError):

　　def __init__(self, form):

　　message = form.get_validate_error()

　　super(FormError, self).__init__(message, extras=form.data)

　　self.level = BaseError.LEVEL_INFO

　　class OrmError(BaseError):

　　def __init__(self, message, status_code=None, extras=None, parent_error=None):

　　super(OrmError, self).__init__(message, status_code, extras, parent_error)

　　self.level = BaseError.LEVEL_ERROR

　　定义了上面的异常信息后，我们在统一处理错误信息的时候就可以像下面这样实现：

　　@app.errorhandler(BaseError)def custom_error_handler(e):

　　if e.level in [BaseError.LEVEL_WARN, BaseError.LEVEL_ERROR]:

　　if isinstance(e, OrmError):

　　app.logger.exception('%s %s' % (e.parent_error, e))

　　else:

　　app.logger.exception(' 错误信息 : %s %s' % (e.extras, e))

　　response = jsonify(e.to_dict())

　　response.status_code = e.status_code

　　return response

　　如此，就兼顾了日志的错误级别和接口返回的数据格式。

　　我们还应该注意什么

　　其实，对于日志的记录，我们前面七七八八也讲了个差不多，在开发的时候如果我们能够注意到上面提到的一些问题，已经能够算是比较合格的打日志了。当然，还有一些小的问题，在最后还是要说明一下。

　　第一个，就是需要我们关键一下性能问题，也就是避免因为日志拖慢应用系统。如果输出的日志信息太多，必然会增加磁盘的写入负担，通常情况下，每小时输出到磁盘的数据量达到几百M 就已经是上限了。

　　第二个，就是不要由于log 语句导致业务过程中断。我们的本意是通过日志来记录系统的一些运行信息，但是， log 语句本身也是有可能发生异常的，如果因为我们的代码，导致日志记录的时候抛出了异常，就真的是得不偿失了。

　　OK ，关于在 Flask 系统中如何进行日志记录，就介绍到这了，其实，上面提到的内容不仅在 Flask 系统中可行，基本上所有的 Web 系统都有参考价值。

来源：简书