Python日志在遇到打开的文件描述符消息时失败

Question

我有一段Python代码，用来在Linux机器上创建一个lvm快照。

#!/usr/bin/env python3.1

import subprocess
import logging
logging.basicConfig(filename='/var/log/lvsnap.log', filemode='w', level=logging.DEBUG)

lvm_vg = 'vg00-crunchbang'
lvm_name = 'root'
lvm_snapshot_size = '100'

def lvmCreateSnapshot(lvm_vg, lvm_name, lvm_snapshot_size):
    return subprocess.check_call(['lvcreate', '-s', '-l', '+' + lvm_snapshot_size + '%FREE', '-n', lvm_name + '-snapshot', lvm_vg + '/' + lvm_name])

logging.debug('logging is working before lvm snapshot')

''' create lvm snapshot '''
lvm_create_snapshot = lvmCreateSnapshot(lvm_vg, lvm_name, lvm_snapshot_size)
if lvm_create_snapshot:
    logging.debug('create lvm snapshot of %s/%s exited with status %s', lvm_vg, lvm_name, lvm_create_snapshot)

logging.debug('logging is working after lvm snapshot')

lvmCreateSnapshot这个函数运行得很好，返回了0，这应该会让if语句里的logging.debug行被执行。

但是实际上并没有这样做，反而我从脚本中得到了以下输出：

> /tmp/lvmsnap.py 
File descriptor 3 (/var/log/lvsnap.log) leaked on lvcreate invocation. Parent PID 7860: python3.1
Logical volume "root-snapshot" created
>

日志的输出是：

> cat /var/log/lvsnap.log 
DEBUG:root:logging is working before lvm snapshot
DEBUG:root:logging is working after lvm snapshot
>

你可以看到，lvm的logging.debug信息缺失了（它应该出现在我创建的两个测试日志信息之间）。

这是为什么呢？我该怎么解决这个问题呢？

Answer 1

你没有调用“缺失的” logging.debug，因为 lvmCreateSnapshot 返回的是零，所以你的 if 条件永远不会满足。你可以尝试

if lvm_create_snapshot:
    logging.debug('Error creating lvm snapshot of %s/%s, exited with status %s', lvm_vg, lvm_name, lvm_create_snapshot)
else:
    logging.debug('created lvm snapshot of %s/%s, lvm_vg, lvm_name)

这样的话，当 subprocess 调用成功时会执行 else，而如果不成功则执行 if 条件，或者

if not lvm_create_snapshot:
    logging.debug('...debugging text...')

只在 subprocess 返回错误时输出调试信息。

编辑：

我刚刚查看了 subprocess.check_call() 的文档，见 http://docs.python.org/library/subprocess.html，文档中说明如果 subprocess.check_call 调用成功，它会返回零；如果不成功，则会抛出一个 CalledProcessError 异常。因此，你需要用常规的 try/except 语句来捕获这个异常。像下面这样的代码就可以了：

try:
    lvmCreateSnapshot(lvm_vg, lvm_name, lvm_snapshot_size)
    logging.debug('created lvm snapshot of %s/%s', lvm_vg, lvm_name)
except CalledProcessError as e:
    logging.debug('Error creating lvm snapshot of {0}/{1}. Return code was {2}'.format(lvm_vg,
        lvm_name, e.returncode))
    raise

最后的 raise 是用来打印错误追踪信息的。当然，你也可以用 return 1 来代替。