本次分析一下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 witha 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 callsall the handlers of this logger to handle the record."""sinfo = Noneif _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 coverfn, lno, func = "(unknown file)", 0, "(unknown function)"else: # pragma: no coverfn, 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 生成日志记录:

    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 createspecialized 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, aswell 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 vetothis and the record is then dropped. Returns a zero value if a recordis to be dropped, else non-zero... versionchanged:: 3.2Allow filters to be just callables."""rv = Truefor f in self.filters:if hasattr(f, 'filter'):result = f.filter(record)else:result = f(record) # assume callable - will raise if notif not result:rv = Falsebreakreturn 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 thelogger hierarchy. If no handler was found, output a one-off errormessage to sys.stderr. Stop searching up the hierarchy whenever alogger with the "propagate" attribute set to zero is found - thatwill be the last logger whose handlers are called."""c = selffound = 0while c:for hdlr in c.handlers:found = found + 1if record.levelno >= hdlr.level:hdlr.handle(record)if not c.propagate:c = None    #break outelse:c = c.parentif (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 ofthe I/O thread lock. Returns whether the filter passed the record foremission."""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 soraises 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.  Ifexception information is present, it is formatted usingtraceback.print_exception and appended to the stream.  If the streamhas an 'encoding' attribute, it is used to determine how to do theoutput to the stream."""try:msg = self.format(record)stream = self.streamstream.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 formatterfor the module."""if self.formatter:fmt = self.formatterelse:fmt = _defaultFormatterreturn 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 adefault as described above. Allow for specialized date formatting withthe optional datefmt argument (if omitted, you get the ISO8601 format).Use a style parameter of '%', '{' or '$' to specify that you want touse one of %-formatting, :meth:`str.format` (``{}``) formatting or:class:`string.Template` formatting in your format string... versionchanged:: 3.2Added 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._fmtself.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 astring formatting operation which yields the returned string.Before formatting the dictionary, a couple of preparatory stepsare carried out. The message attribute of the record is computedusing LogRecord.getMessage(). If the formatting string uses thetime (as determined by a call to usesTime(), formatTime() iscalled 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_textif 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_formatdef usesTime(self):return self._fmt.find(self.asctime_search) >= 0def format(self, record):return self._fmt % record.__dict__

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

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

请大家多多指点。