python日志打印被调用的类、方法和文件名

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

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全部打印出来：

(<frame object at 0xe0faef0>, ‘/python-chain-log/CLog.py’, 28, ‘get_meta_data’, [’ frames = inspect.stack()\n’], 0)
(<frame object at 0xe0fad00>, ‘/python-chain-log/CLog.py’, 46, ‘write’, [’ chain = self.get_meta_data()\n’], 0)
(<frame object at 0xe0f4280>, ‘example.py’, 9, ‘foo’, [" log.write(‘hello world’)\n"], 0)
(<frame object at 0xe088400>, ‘example.py’, 13, ‘’, [" fc.foo(‘def’)\n"], 0)
从里面我们获取的信息，就能够得到CLog获取到的信息了。