本次分析一下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
