CLog的一个例子

我在文章开头，先告诉大家，CLog是干什么的，看下面的例子：

__author__ = \'baniu.yao\'

from CLog import CLog

class FooClass(object):

    def foo(self, text):
        log = CLog()
        log.write(\'hello world\')

if __name__ == \'__main__\':
    fc = FooClass()
    fc.foo(\'def\')

运行python example.py后，日志如下：

2014-03-30 19:09:35,582 [example.py:FooClass() --> example.py:foo(\'def\')] hello world

CLog的作用，就是在打印日志的同时，把文件名，类名，方法名和方法的参数都打印出来了。而我们在使用CLog的时候，是完全透明的，不需要关心这些细节，这一切都是CLog完成的。

CLog在这里：https://github.com/baniuyao/Python-CLog

为什么我要开发一个Python日志模块

之前我一直使用Python自带的logging模块来打印日志，他功能强大，可以定制非常多的东西，但唯一让我不爽的，就是当我在看我打印的日志的时候，我根本不知道这条日志是在哪个地方打印的。特别是最近我在开发一个报警系统，设计到报警规则的解析，算是一个比较复杂的系统。我需要一个强大的日志能够帮我追踪程序的每一次关键的逻辑判断，简而言之，我要知道我的这条日志，是在哪个文件的哪个类里的哪个方法中打印的，最好还能知道方法调用的参数。

比如一个foo.py：

def Foo(object):
    def foo(self):
        log.log(\'hello world\')
if __name__ == \'__main__\':
    f = Foo()
    f.foo()

然后日志中是这样的：
foo.py:Foo() –> foo.py:foo() hello world

是不是很棒？

基于这个需求，我开发了Python-CLog。其中的CLog是Chain Log的简称，因为CLog的目的是打印出整个调用链。

Python logging模块和CLog对比

logging模块支持打印调用logging方法的函数名和模块名，但这个功能非常的简陋，只支持当前调用这个logging方法所在的函数，不支持链式的追踪。我们看下面这个例子。

代码Foo1_logging.py：

import logging
from Foo2 import Foo2

logging.basicConfig(filename=\"./use_logging.log\", 
                    format=\'%(asctime)-6s: %(name)s - %(levelname)s - %(module)s - %(funcName)s - %(lineno)d - %(message)s\', 
                    level=logging.DEBUG)

class Foo1(object):
    def foo(self, text):
        f2 = Foo2()
        f2.foo(\'foo2\')
        logging.info(\'use logging in foo1\')

if __name__ == \'__main__\':
    f = Foo1()
    f.foo(\'foo1\')

代码Foo2_logging.py:

import logging

logging.basicConfig(filename=\"./use_logging.log\", 
                    format=\'%(asctime)-6s: %(name)s - %(levelname)s - %(module)s - %(funcName)s - %(lineno)d - %(message)s\', 
                    level=logging.DEBUG)

class Foo2(object):
    def foo(self, text):
        logging.info(\'use logging in foo2\')

使用logging模块的结果

我运行了Foo1_logging.py，获取到的use_logging.log如下：

2014-03-30 23:28:25,795: root - INFO - Foo2 - foo - 11 - use logging in foo2
2014-03-30 23:28:34,619: root - INFO - Foo2 - foo - 11 - use logging in foo2
2014-03-30 23:28:34,619: root - INFO - Foo1 - foo - 14 - use logging in foo1

如果说不看代码内容，我想能看懂Foo1和Foo2的依赖关系是非常困难的吧。如果还有并发的请求，那么日志几乎是没有用处的。而且，Foo1和Foo2的foo方法都接受一个参数，这个参数，也没有在日志里反应出来。

我们看看CLog对于这种情况，日志是怎样的，代码有稍许变动。

Foo1_cl.py:

from Foo2_cl import Foo2
from CLog import CLog

class Foo1(object):
    def foo(self, text):
        f2 = Foo2()
        f2.foo(\'foo2\')
        cl = CLog()
        cl.write(\'use CL in foo1\')

if __name__ == \'__main__\':
    f = Foo1()
    f.foo(\'foo1\')

Foo2_cl.py:

from CLog import CLog

class Foo2(object):
    def foo(self, text):
        cl = CLog()
        cl.write(\'use clog in foo2\')

使用CLog的日志：

2014-03-30 23:35:18,630 [Foo1_cl.py:Foo2() --> Foo1_cl.py:foo(\'foo1\') --> Foo2_cl.py:foo(\'foo2\')] use clog in foo2
2014-03-30 23:35:18,630 [Foo1_cl.py:Foo1() --> Foo1_cl.py:foo(\'foo1\')] use CL in foo1

是不是清楚多了呢？调用链非常清楚，也知道foo的参数是什么，相比logging的日志，大家可以比较一下。

CLog是怎么工作的

不知道有多少人读过《Python源码分析》，Python在执行代码的时候，有一个栈帧frame的概念，我们把它理解成一张纸片，而运行一段Python代码，就是用线把一串纸片串起来执行。CLog就是调用了Python自带的inspect模块，来获取到执行时代码的frame，从中找到我们需要的信息，我们还是看example.py，这次我把CLog模块的代码改了一下，将调用write时候的frames全部打印出来：

(, \'/python-chain-log/CLog.py\', 28, \'get_meta_data\', [\'        frames = inspect.stack()\\n\'], 0)
(, \'/python-chain-log/CLog.py\', 46, \'write\', [\'        chain = self.get_meta_data()\\n\'], 0)
(, \'example.py\', 9, \'foo\', [\"        log.write(\'hello world\')\\n\"], 0)
(, \'example.py\', 13, \'\', [\"    fc.foo(\'def\')\\n\"], 0)

从里面我们获取的信息，就能够得到CLog获取到的信息了。

TOOD

CLog是我在上周五花了半天开发的，下一步我会添加CLog在终端打印日志的功能，目前仅仅支持打印到日志文件。