pythonlogging模块教学（详解Python logging调用Logger.info方法的处理过程）

pythonlogging模块教学

详解Python logging调用Logger.info方法的处理过程

本次分析一下logger.info的流程

1. logger.info源码:

?

1 2 3 4 5 6 7 8 9 10 11

def info(self, msg, *args, **kwargs):  """  log 'msg % args' with severity 'info'.    to pass exception information, use the keyword argument exc_info with  a true value, e.g.    logger.info("houston, we have a %s", "interesting problem", exc_info=1)  """  if self.isenabledfor(info):   self._log(info, msg, args, **kwargs)

注释中反应了可以通过 msg和不定参数args来进行日志的格式化。
真实的调用为：_log方法：

2. logger._log方法:

?

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24

def _log(self, level, msg, args, exc_info=none, extra=none, stack_info=false):  """  low-level logging routine which creates a logrecord and then calls  all the handlers of this logger to handle the record.  """  sinfo = none  if _srcfile:   #ironpython doesn't track python frames, so findcaller raises an   #exception on some versions of ironpython. we trap it here so that   #ironpython can use logging.   try:    fn, lno, func, sinfo = self.findcaller(stack_info)   except valueerror: # pragma: no cover    fn, lno, func = "(unknown file)", 0, "(unknown function)"  else: # pragma: no cover   fn, lno, func = "(unknown file)", 0, "(unknown function)"  if exc_info:   if isinstance(exc_info, baseexception):    exc_info = (type(exc_info), exc_info, exc_info.__traceback__)   elif not isinstance(exc_info, tuple):    exc_info = sys.exc_info()  record = self.makerecord(self.name, level, fn, lno, msg, args,         exc_info, func, extra, sinfo)  self.handle(record)

最后两行：

生成日志记录：

?

1	record = self.makerecord(self.name, level, fn, lno, msg, args, exc_info, func, extra, sinfo)

处理日志记录

?

1	self.handle(record)

2 生成日志记录:

?

1 2 3 4 5 6 7 8 9 10 11 12 13 14

def makerecord(self, name, level, fn, lno, msg, args, exc_info,     func=none, extra=none, sinfo=none):  """  a factory method which can be overridden in subclasses to create  specialized logrecords.  """  rv = _logrecordfactory(name, level, fn, lno, msg, args, exc_info, func,        sinfo)  if extra is not none:   for key in extra:    if (key in ["message", "asctime"]) or (key in rv.__dict__):     raise keyerror("attempt to overwrite %r in logrecord" % key)    rv.__dict__[key] = extra[key]  return rv

调用_logrecordfactory初始化一个日志记录实例，_logrecordfactory 其实就是logrecord类，初始化时，可能包含logger的name, level、调用的函数、行号、日志字符串、模板参数、堆栈信息等。

再看extra信息，extra到底有何用？现在从代码中可以看到，只是更新到生成的日志记录实例的__dict__中去.猜测：肯定会在生成最终的日志字符串的时候会用到。继续往下看。

3 处理日志记录self.handle(record):

logger继承自filterer,

?

1 2 3 4 5 6 7 8 9

def handle(self, record):  """  call the handlers for the specified record.    this method is used for unpickled records received from a socket, as  well as those created locally. logger-level filtering is applied.  """  if (not self.disabled) and self.filter(record):   self.callhandlers(record)

3.1 if语句中有一self.filter(record)的判断，看函数名，是来筛选是否要继续处理消息的，其核心源码如下：

?

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22

def filter(self, record):  """  determine if a record is loggable by consulting all the filters.    the default is to allow the record to be logged; any filter can veto  this and the record is then dropped. returns a zero value if a record  is to be dropped, else non-zero.    .. versionchanged:: 3.2     allow filters to be just callables.  """  rv = true  for f in self.filters:   if hasattr(f, 'filter'):    result = f.filter(record)   else:    result = f(record) # assume callable - will raise if not   if not result:    rv = false    break  return rv

可以看到， 如果在handler中的filter中如果有返回为false或空，则会屏蔽对应的record,返回true或部位空的值，则会将record放行。那么我们就可以自定义自己的filter。

3.2 让logger中所有的handles去处理record:

?

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29

def callhandlers(self, record):   """   pass a record to all relevant handlers.     loop through all handlers for this logger and its parents in the   logger hierarchy. if no handler was found, output a one-off error   message to sys.stderr. stop searching up the hierarchy whenever a   logger with the "propagate" attribute set to zero is found - that   will be the last logger whose handlers are called.   """   c = self   found = 0   while c:    for hdlr in c.handlers:     found = found + 1     if record.levelno >= hdlr.level:      hdlr.handle(record)    if not c.propagate:     c = none #break out    else:     c = c.parent   if (found == 0):    if lastresort:     if record.levelno >= lastresort.level:      lastresort.handle(record)    elif raiseexceptions and not self.manager.emittednohandlerwarning:     sys.stderr.write("no handlers could be found for logger"          " \"%s\"\n" % self.name)     self.manager.emittednohandlerwarning = true

代码中会去循环调用当前logger的所有handlers去处理record,for循环部分,之后，如果当前的logger的propagate的值为false或空，则不向logger的父logger传递，即向上传递。

4. handler 中的 handler(record) 部分：

?

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17

def handle(self, record):   """   conditionally emit the specified logging record.     emission depends on filters which may have been added to the handler.   wrap the actual emission of the record with acquisition/release of   the i/o thread lock. returns whether the filter passed the record for   emission.   """   rv = self.filter(record)   if rv:    self.acquire()    try:     self.emit(record)    finally:     self.release()   return rv

可以看到， handler在处理record时， 会去加锁，然后调用self.emit(record)方法去处理。

4.1 emit(record)

?

1 2 3 4 5 6 7 8 9

def emit(self, record):   """   do whatever it takes to actually log the specified logging record.     this version is intended to be implemented by subclasses and so   raises a notimplementederror.   """   raise notimplementederror('emit must be implemented '          'by handler subclasses')

看到需要由子类去实现，以streamhandler为例子：

?

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19

def emit(self, record):   """   emit a record.     if a formatter is specified, it is used to format the record.   the record is then written to the stream with a trailing newline. if   exception information is present, it is formatted using   traceback.print_exception and appended to the stream. if the stream   has an 'encoding' attribute, it is used to determine how to do the   output to the stream.   """   try:    msg = self.format(record)    stream = self.stream    stream.write(msg)    stream.write(self.terminator)    self.flush()   except exception:    self.handleerror(record)

4.2 handler.format(record):

?

1 2 3 4 5 6 7 8 9 10 11 12

def format(self, record):  """  format the specified record.    if a formatter is set, use it. otherwise, use the default formatter  for the module.  """  if self.formatter:   fmt = self.formatter  else:   fmt = _defaultformatter  return fmt.format(record)

如果handler有自定义的formatter就用自定义的，如果没有则用默认的formatter的实例， 初始化元源码为：

?

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21

def __init__(self, fmt=none, datefmt=none, style='%'):  """  initialize the formatter with specified format strings.    initialize the formatter either with the specified format string, or a  default as described above. allow for specialized date formatting with  the optional datefmt argument (if omitted, you get the iso8601 format).    use a style parameter of '%', '{' or '$' to specify that you want to  use one of %-formatting, :meth:`str.format` (``{}``) formatting or  :class:`string.template` formatting in your format string.    .. versionchanged:: 3.2   added the ``style`` parameter.  """  if style not in _styles:   raise valueerror('style must be one of: %s' % ','.join(        _styles.keys()))  self._style = _styles[style][0](fmt)  self._fmt = self._style._fmt  self.datefmt = datefmt

有三个参数：

• fmt: 格式化模板
• datefmt: 时间格式化参数
• style: 日志格式化的样式。

style有三种：

?

1 2 3 4

_styles = {  '%': (percentstyle, basic_format),  '{': (strformatstyle, '{levelname}:{name}:{message}'),  '$': (stringtemplatestyle, '${levelname}:${name}:${message}'),

可以看出对应到：% 操作符的格式化， format方法的格式化以及template的格式化。

formatter的format方法源码为：

?

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29

def format(self, record):  """  format the specified record as text.  the record's attribute dictionary is used as the operand to a  string formatting operation which yields the returned string.  before formatting the dictionary, a couple of preparatory steps  are carried out. the message attribute of the record is computed  using logrecord.getmessage(). if the formatting string uses the  time (as determined by a call to usestime(), formattime() is  called to format the event time. if there is exception information,  it is formatted using formatexception() and appended to the message.  """  record.message = record.getmessage()  if self.usestime():   record.asctime = self.formattime(record, self.datefmt)  s = self.formatmessage(record)  if record.exc_info:   # cache the traceback text to avoid converting it multiple times   # (it's constant anyway)   if not record.exc_text:    record.exc_text = self.formatexception(record.exc_info)  if record.exc_text:   if s[-1:] != "\n":    s = s + "\n"   s = s + record.exc_text  if record.stack_info:   if s[-1:] != "\n":    s = s + "\n"   s = s + self.formatstack(record.stack_info)

看到会调用record.getmessage(),这里仅仅是获取我们需要的日志信息。

之后会调用s = self.formatmessage(record):

?

1 2	def formatmessage(self, record):  return self._style.format(record)

其实是调用了当前style的format方法，以%这一类型为例percentstyle：

?

1 2 3 4 5 6 7 8 9 10 11 12 13 14

class percentstyle(object):    default_format = '%(message)s'  asctime_format = '%(asctime)s'  asctime_search = '%(asctime)'    def __init__(self, fmt):   self._fmt = fmt or self.default_format    def usestime(self):   return self._fmt.find(self.asctime_search) >= 0    def format(self, record):   return self._fmt % record.__dict__

从其中的format方法可以看出，是针对record的__dict__属性中的所有参数进行格式化，这下，就清楚了之前的extra参数是干嘛用的了：可以在formatter中加入自己自定义的一些参数，如固定的用户信息等等。

之后，将最终的message flush到对应的stream里面去就行了，就是整个流程:

以上就是本文的全部内容，希望对大家的学习有所帮助，也希望大家多多支持开心学习网。

原文链接：https://segmentfault.com/a/1190000018119406