Python loggingモジュールのソースコード(example付き)を読み取る

自分のBlogがPython loggingモジュールの深さに欠けている文章を探してみました.実はこのモジュールはとてもよく使われていて、非常に多くの乱用もあります.ソースコードを見てloggingモジュールに属する文章を詳しく記録します.
loggingモジュール全体の主要部分1700行コードは、まだ簡単です.私たちは実際の行動から皆さんをコードに連れて行きます.
 
ロゴを書いているとinfoの時私たちは何をしていましたか?

def info(msg, *args, **kwargs):
    if len(root.handlers) == 0:
        basicConfig()
    root.info(msg, *args, **kwargs)

デフォルトで使用されているrootが表示されます.infoインタフェース.
直接呼び出すとbasicConfigの初期構成がデフォルトで呼び出されます.

_acquireLock()
try:
    if len(root.handlers) == 0:
        filename = kwargs.get("filename")
        if filename:
            mode = kwargs.get("filemode", 'a')
            hdlr = FileHandler(filename, mode)
        else:
            stream = kwargs.get("stream")
            hdlr = StreamHandler(stream)
        fs = kwargs.get("format", BASIC_FORMAT)
        dfs = kwargs.get("datefmt", None)
        fmt = Formatter(fs, dfs)
        hdlr.setFormatter(fmt)
        root.addHandler(hdlr)
        level = kwargs.get("level")
        if level is not None:
            root.setLevel(level)
finally:
    _releaseLock()

最初の行はロックを持っていて、loggingモジュールはスレッドの安全を考慮しているはずだと簡単に判断できます.
ここではfilenameがないので、ストリームhandler StreamHandlerを直接初期化します.ここでNoneが入力され、最後に標準出力sysが得られます.stderr.
その後、いくつかのデフォルト構成が得られ、出力のフォーマット方法を設定して最後にhandlerをセットします.
最後にrootにこのストリーム処理のhandlerを追加します.
完了したらロックを解除します.
これでbaseConfigの初期化を完了しました.もちろん、普段見ている他のblogではconfigを初期化する方法を紹介しているに違いありませんが、実際には上のコードのパラメータを上書きしています.カスタムパラメータに変更します.
 
皆さんが聞くかもしれませんinfoというrootは何の定義ですか?
コードを見てみましょう.

root = RootLogger(WARNING)
Logger.root = root
Logger.manager = Manager(Logger.root)

 
上記のコードはloggingがimportされたときに実行されるのでrootは直接付与されます.RootLoggerが初期化されたときに何が起こったか見てみましょう.

class RootLogger(Logger):
    def __init__(self, level):
        """
        Initialize the logger with the name "root".
        """
        Logger.__init__(self, "root", level)

父のロゴを見てみましょうinit__ 何が叶うの

class Logger(Filterer):
    def __init__(self, name, level=NOTSET):
        Filterer.__init__(self)
        self.name = name
        self.level = _checkLevel(level)
        self.parent = None
        self.propagate = 1
        self.handlers = []
        self.disabled = 0

ここでデフォルトのnameはrootです.その後、これらのパラメータを初期化して最後にこのloggerオブジェクトを返します.
loggerには多くの方法がある.info .error .warnなどのログを直接印刷する方法.

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)

loggingを呼び出すとinfoの時はlogger('root')を呼び出しています.info 
 
それを知ったら、loggerがどのようにログを打ったのかを見てみましょう.
self._を呼び出すlogメソッドはlogger.を呼び出すことですlogメソッド

def _log(self, level, msg, args, exc_info=None, extra=None):
    if _srcfile:
        try:
            fn, lno, func = self.findCaller()
        except ValueError:
            fn, lno, func = "(unknown file)", 0, "(unknown function)"
    else:
        fn, lno, func = "(unknown file)", 0, "(unknown function)"
    if exc_info:
        if not isinstance(exc_info, tuple):
            exc_info = sys.exc_info()
    record = self.makeRecord(self.name, level, fn, lno, msg, args, exc_info, func, extra)
    self.handle(record)

特別なパラメータ構成がなければ
record呼び出しmakeRecordメソッドが直接初期化されます.最後に自分のhandleメソッドを呼び出します.まずmakeRecordの方法を見てみましょう.
このコードを見る前に、logRecordがloggingログモジュールにある意味を明確にすることができます.つまり、印刷するたびにログがログレコードのインスタンスになります.コードを見てみましょう

def __init__(self, name, level, pathname, lineno,
             msg, args, exc_info, func=None):
    """
    Initialize a logging record with interesting information.
    """
    ct = time.time()
    self.name = name
    self.msg = msg
    #
    # The following statement allows passing of a dictionary as a sole
    # argument, so that you can do something like
    #  logging.debug("a %(a)d b %(b)s", {'a':1, 'b':2})
    # Suggested by Stefan Behnel.
    # Note that without the test for args[0], we get a problem because
    # during formatting, we test to see if the arg is present using
    # 'if self.args:'. If the event being logged is e.g. 'Value is %d'
    # and if the passed arg fails 'if self.args:' then no formatting
    # is done. For example, logger.warn('Value is %d', 0) would log
    # 'Value is %d' instead of 'Value is 0'.
    # For the use case of passing a dictionary, this should not be a
    # problem.
    # Issue #21172: a request was made to relax the isinstance check
    # to hasattr(args[0], '__getitem__'). However, the docs on string
    # formatting still seem to suggest a mapping object is required.
    # Thus, while not removing the isinstance check, it does now look
    # for collections.Mapping rather than, as before, dict.
    if (args and len(args) == 1 and isinstance(args[0], collections.Mapping)
        and args[0]):
        args = args[0]
    self.args = args
    self.levelname = getLevelName(level)
    self.levelno = level
    self.pathname = pathname
    try:
        self.filename = os.path.basename(pathname)
        self.module = os.path.splitext(self.filename)[0]
    except (TypeError, ValueError, AttributeError):
        self.filename = pathname
        self.module = "Unknown module"
    self.exc_info = exc_info
    self.exc_text = None      # used to cache the traceback text
    self.lineno = lineno
    self.funcName = func
    self.created = ct
    self.msecs = (ct - long(ct)) * 1000
    self.relativeCreated = (self.created - _startTime) * 1000
    if logThreads and thread:
        self.thread = thread.get_ident()
        self.threadName = threading.current_thread().name
    else:
        self.thread = None
        self.threadName = None
    if not logMultiprocessing:
        self.processName = None
    else:
        self.processName = 'MainProcess'
        mp = sys.modules.get('multiprocessing')
        if mp is not None:
            # Errors may occur if multiprocessing has not finished loading
            # yet - e.g. if a custom import hook causes third-party code
            # to run when multiprocessing calls import. See issue 8200
            # for an example
            try:
                self.processName = mp.current_process().name
            except StandardError:
                pass
    if logProcesses and hasattr(os, 'getpid'):
        self.process = os.getpid()
    else:
        self.process = None

印刷に必要な現在のタイムスタンプ、名前が印刷される内容など、さまざまなパラメータが表示されます.いくつかのパラメータが含まれており、印刷する必要がある場合のレベルです.このlogRecordインスタンスには割り当てられます.
このレコードを手に入れたらloggerを実行します.handleメソッドです.レコードインスタンスオブジェクトが転送されます.

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)

もしself.フィルターで濾過すると.ここのhandleメソッドはloggerです.filterメソッドはベースクラスfilterです.filterここでは、以前にaddからhandlerに入ったfilterを取りに行きます.filterメソッドは配列です.LoggerとHandlerクラスの親はFiltererクラスです.彼はselfを維持します.filtersの配列.
そしてcallHandlersメソッドを呼び出します

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) and raiseExceptions and not self.manager.emittedNoHandlerWarning:
        sys.stderr.write("No handlers could be found for logger"
                         " \"%s\"
" % self.name)
        self.manager.emittedNoHandlerWarning = 1

loggerに掛けられたhandler配列により,handleメソッドを呼び出して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クラスの方法です.さっき私たちが初期化したのはStreamHandlerメソッドで、Handlerクラスはその親です.
次にhandlerの独自のfilterメソッドが再び呼び出されます.フィルタリング後も結果が出た場合は、ロックをかけてemitメソッドを呼び出してログを開始します.
ここでは、StreamHandlerメソッドのemitメソッドを使用します.

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
        fs = "%s
"
        if not _unicode: #if no unicode support...
            stream.write(fs % msg)
        else:
            try:
                if (isinstance(msg, unicode) and
                    getattr(stream, 'encoding', None)):
                    ufs = u'%s
'
                    try:
                        stream.write(ufs % msg)
                    except UnicodeEncodeError:
                        #Printing to terminals sometimes fails. For example,
                        #with an encoding of 'cp1251', the above write will
                        #work if written to a stream opened or wrapped by
                        #the codecs module, but fail when writing to a
                        #terminal even when the codepage is set to cp1251.
                        #An extra encoding step seems to be needed.
                        stream.write((ufs % msg).encode(stream.encoding))
                else:
                    stream.write(fs % msg)
            except UnicodeError:
                stream.write(fs % msg.encode("UTF-8"))
        self.flush()
    except (KeyboardInterrupt, SystemExit):
        raise
    except:
        self.handleError(record)

そして流れの中まで楽しく書いて、流れ全体を終わりました.
 
実はこの流れを理解すれば、ログを打つのは簡単です.通常の使用では、このプロセスで構成を変更したり、初期化時にrootを使用せずにカスタムの名前を使用したりして、カスタムの構成XDを追加することはできません.
 
 
Reference:
https://juejin.im/post/5b13fdd0f265da6e0b6ff3ddPycon 2018はロゴモジュールでPythonログを簡単に記録