首页

    调用多个python logger

    标签:python

    工作中,日志除了一般格式的打印,还需要以json格式打印,以上报给ELK,这时想到的是

    • 在日志模块定义两个logger:root_logger和rootjson_logger
    • 写一个info()方法,里面有分别调用root_logger和rootjson_logger的info()方法
    • 需要日志打印时,调用刚定义的info()方法
    import logging
    import logging.config
    import os
    from pythonjsonlogger import jsonlogger
    
    
    def json_formatter():
        log_format_keys = [
            'asctime', 'created', 'levelname', 'filename', 'lineno', 'module',
            'message', 'name', 'pathname', 'process', 'processName', 'thread',
            'threadName'
        ]
    
        def log_format(x):
            return ['%({0:s})'.format(i) for i in x]
    
        custom_format = ' '.join(log_format(log_format_keys))
        log_json_format = jsonlogger.JsonFormatter(custom_format)
        return log_json_format
    
    
    logging.config.fileConfig('logging.conf', disable_existing_loggers=False)
    
    rootjson_logger = logging.getLogger("rootjson")
    rootjson_logger.handlers[0].setFormatter(json_formatter())
    
    root_logger = logging.getLogger("root")
    
    def info(msg, *args, extra={}, exc_info=True, **kwargs):
        rootjson_logger.info(msg, extra={'order_log_json': extra}, *args, exc_info=exc_info, **kwargs)
        root_logger.info(msg + ', extra: %s', extra, *args, exc_info=exc_info, **kwargs)
    

    调用后发现打印的日志的filename,lineno是上面定义的info()方法的文件名和行数

    root

    2019-05-26 20:57:57,702 INFO custom_logger_overwrite.py:66 pid-27870 test, extra: {'a': 1}
    NoneType: None
    

    rootjson

    {"asctime": "2019-05-26 20:57:57,701", "created": 1558875477.701954, "levelname": "INFO", "filename": "custom_logger_overwrite.py", "lineno": 65, "module": "custom_logger_overwrite", "message": "test", "name": "rootjson", "pathname": "custom_logger_overwrite.py", "process": 27870, "processName": "MainProcess", "thread": 140171730773824, "threadName": "MainThread", "exc_info": "NoneType: None", "order_log_json": {"a": 1}}
    

    这是显而易见的,然而还是需要将filename,lineno置为调用方的filename,lineno
    注意到logging模块的_log方法,info(),error()...这些方法都会调用它

    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)
    

    本来想重写findCaller方法的,发现看不懂,好在还有makeRecord方法不复杂,可以改

    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
    

    makeRecord方法会将extra参数(info方法传进去的)遍历,传给LogRecord并返回.所以只需用inspect模块反射,获取调用方的filename和lineno给extra参数就行了

    import inspect
    import os
    
    
    def info(msg, *args, extra={}, exc_info=True, **kwargs):
        caller = inspect.getframeinfo(inspect.stack()[1][0])
        filename = os.path.basename(caller.filename)
        rootjson_logger.info(msg, extra={'order_log_json': extra, 'filename': filename, 'lineno': caller.lineno},
                             *args, exc_info=exc_info, **kwargs)
        root_logger.info(msg + ', extra: %s', extra, extra={'filename': filename, 'lineno': caller.lineno},
                         *args, exc_info=exc_info, **kwargs)
    

    修改后,调用info方法,抛出KeyError: "Attempt to overwrite 'filename' in LogRecord",这不就是上面makeRecord方法里抛出的吗。

    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]
    

    if后面部分是为了防止extra参数对LogRecord内属性的修改.现在要将filename,lineno改回来,就只能允许修改了
    自定义logger,并重写makeRecord方法,将修改字段的限制去掉

    class CustomLogger(logging.Logger):
        super(logging.Logger)
    
        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 = logging.LogRecord(name, level, fn, lno, msg, args, exc_info, func,
                                   sinfo)
            if extra is not None:
                for key in extra:
                    if key in ["message", "asctime"]:
                        raise KeyError("Attempt to overwrite %r in LogRecord" % key)
                    rv.__dict__[key] = extra[key]
            return rv
    
    
    logging.setLoggerClass(CustomLogger)
    

    这样改了之后,有点美中不足的是没异常时的日志会多出来NoneType: None

    root

    2019-05-26 20:57:57,702 INFO custom_logger_overwrite.py:66 pid-27870 test, extra: {'a': 1}
    NoneType: None
    

    rootjson

    {"asctime": "2019-05-26 20:57:57,701", "created": 1558875477.701954, "levelname": "INFO", "filename": "custom_logger_overwrite.py", "lineno": 65, "module": "custom_logger_overwrite", "message": "test", "name": "rootjson", "pathname": "custom_logger_overwrite.py", "process": 27870, "processName": "MainProcess", "thread": 140171730773824, "threadName": "MainThread", "exc_info": "NoneType: None", "order_log_json": {"a": 1}}
    

    出现这种情况是因为不想每次调用原本的info方法时,都要传入exc_info=True参数,就在封装的info方法传入默认参数exc_info=True

    def info(msg, *args, extra={}, exc_info=True, **kwargs):
        ....
        rootjson_logger.info(msg, extra={'order_log_json': extra, 'filename': filename, 'lineno': caller.lineno},
                             *args, exc_info=exc_info, **kwargs)
        root_logger.info(msg + ', extra: %s', extra, extra={'filename': filename, 'lineno': caller.lineno},
                         *args, exc_info=exc_info, **kwargs)
    

    注意到_log方法有对exc_info的处理

    def _log(self, level, msg, args, exc_info=None, extra=None, stack_info=False):
        ...
        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)
    

    exc_info会运行到第7行,sys.exc_info()

    If no exception is being handled anywhere on the stack, a tuple containing three None values is returned. Otherwise, the values returned are (type, value, traceback)

    没有异常时,exc_info=(None, None, None),然后进入自定义logger里的makeRecord方法,因此只需

    class CustomLogger(logging.Logger):
        super(logging.Logger)
    
        def makeRecord(self, name, level, fn, lno, msg, args, exc_info,
                       func=None, extra=None, sinfo=None):
            if exc_info == (None, None, None):
                exc_info = None
            rv = logging.LogRecord(name, level, fn, lno, msg, args, exc_info, func,
                                   sinfo)
            ...