Python logging fails when open file descriptor message encountered

Question

I have the following Python code to create an lvm snapshot on a Linux machine.

#!/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 runs fine and exits with 0 which should then run the logging.debug line in the if statement. However this does not happen and instead I received the following output from the script:

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

The output of the log is:

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

Which, as you can see has the lvm logging.debug message missing (it should appear between the 2 test logging messages I created).

Why is this happening and how can I fix it?

Chris · Accepted Answer · 2011-07-15T09:04:11.380

You are not invoking the "missing" logging.debug since lvmCreateSnapshot returns zero and your if condition is therefore never met. Try

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)

so that the else is exectuded on a successful subprocess call and the if condition is otherwise exectuded, or

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

to only output a debugging message if subprocess returns an error.

EDIT:

I have just looked at the documentation for subprocess.check_call(), see http://docs.python.org/library/subprocess.html, which states that subprocess.check_call returns zero if the subprocess call was successful and raises a CalledProcessError exception otherwise. Therefore you have to catch this exception with the usual try/except block. Something like the following should suffice:

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

The final raise is there to print the traceback. You could of course use something like return 1 instead.

Thanks Chris, using "if not" achieves the correct result. I have come from writing bash scripts and had become confused as this seemed counter intuitive. Would another way to say it be "If lvm_create_snapshot is `not` a failure then proceed otherwise raise CalledProcessError exception"? — jelloir, Jul 11 '11 at 08:57
No problem. If `lvm_create_snapshot` is a failure then it should automatically raise a `CalledProcessError` exception; you do not need to do this but you do (if you want to) need to write code to handle this exception if it occurs. I have added an example of what you could do the my original answer. — Chris, Jul 11 '11 at 14:56

Python logging fails when open file descriptor message encountered

1 Answers1