python

超轻量级php框架startmvc

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

更新时间:2020-06-24 09:48:01 作者:startmvc
本次分析一下Logger.info的流程1.Logger.info源码:definfo(self,msg,*args,**kwargs):"""Log'msg%args'withseverity'

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

1. Logger.info源码:


 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方法:


 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)

最后两行:

生成日志记录:


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

处理日志记录


self.handle(record)

2 生成日志记录:


 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,


 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)的判断,看函数名,是来筛选是否要继续处理消息的,其核心源码如下:


 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:


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) 部分:


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)


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为例子:


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):


 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的实例, 初始化元源码为:


 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有三种:


_STYLES = {
 '%': (PercentStyle, BASIC_FORMAT),
 '{': (StrFormatStyle, '{levelname}:{name}:{message}'),
 '$': (StringTemplateStyle, '${levelname}:${name}:${message}'),

可以看出对应到:% 操作符的格式化, format方法的格式化以及Template的格式化。

Formatter的format方法源码为:


 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):


 def formatMessage(self, record):
 return self._style.format(record)

其实是调用了当前style的format方法,以%这一类型为例PercentStyle:


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里面去就行了,就是整个流程:

以上就是本文的全部内容,希望对大家的学习有所帮助,也希望大家多多支持脚本之家。

Python logging调用Logger.info Python 调用Logger.info