Comment 4 for bug 497258

I did add a sync to the following file

/usr/lib/python2.6/dist-packages/VMBuilder/disk.py

Here

    def umount(self):
        self.vm.cancel_cleanup(self.umount)
        if (self.type != TYPE_SWAP) and not self.dummy:
            logging.debug('Syncing')
            run_cmd('sync')
            logging.debug('Unmounting %s', self.mntpath)
            run_cmd('umount', self.mntpath)

But there is a umount happening before that function is called.

I ran vmbuilder in debug mode and here are the pertinent messages:

===================
2009-12-23 09:18:43,386 DEBUG : Reading package lists...
2009-12-23 09:18:43,386 DEBUG : cleaning apt
2009-12-23 09:18:43,386 DEBUG : ['chroot', '/home/ubuntu/Data/tmp/vmbuilderYt3CgM/root', 'apt-get', 'clean']
2009-12-23 09:18:43,613 DEBUG : Unmounting volatile lrm filesystems
2009-12-23 09:18:43,614 DEBUG : Unbinding /dev and /proc filesystems
2009-12-23 09:24:43,714 DEBUG : ['umount', '/home/ubuntu/Data/tmp/vmbuilderYt3CgM/root/dev/pts']
2009-12-23 09:24:43,718 DEBUG : ['umount', '/home/ubuntu/Data/tmp/vmbuilderYt3CgM/root/dev']
2009-12-23 09:24:43,723 DEBUG : ['umount', '/home/ubuntu/Data/tmp/vmbuilderYt3CgM/root/proc']
2009-12-23 09:24:43,727 INFO : umount: /home/ubuntu/Data/tmp/vmbuilderYt3CgM/root/proc: device is busy.
2009-12-23 09:24:43,728 INFO : (In some cases useful info about processes that use
2009-12-23 09:24:43,729 INFO : the device is found by lsof(8) or fuser(1))
2009-12-23 09:24:43,729 DEBUG : Oh, dear, an exception occurred
2009-12-23 09:24:43,729 INFO : Cleaning up
2009-12-23 09:24:43,729 DEBUG : ['umount', '/home/ubuntu/Data/tmp/vmbuilderYt3CgM/root/proc']
2009-12-23 09:24:43,733 DEBUG : umount: /home/ubuntu/Data/tmp/vmbuilderYt3CgM/root/proc: device is busy.
2009-12-23 09:24:43,734 DEBUG : (In some cases useful info about processes that use
2009-12-23 09:24:43,734 DEBUG : the device is found by lsof(8) or fuser(1))
2009-12-23 09:24:43,734 DEBUG : ['umount', '/home/ubuntu/Data/tmp/vmbuilderYt3CgM/root/dev/pts']
2009-12-23 09:24:43,739 DEBUG : umount: /home/ubuntu/Data/tmp/vmbuilderYt3CgM/root/dev/pts: not mounted
2009-12-23 09:24:43,739 DEBUG : ['umount', '/home/ubuntu/Data/tmp/vmbuilderYt3CgM/root/dev']
2009-12-23 09:24:43,744 DEBUG : umount: /home/ubuntu/Data/tmp/vmbuilderYt3CgM/root/dev: not mounted
2009-12-23 09:24:43,744 DEBUG : Syncing
2009-12-23 09:24:43,744 DEBUG : ['sync']
2009-12-23 09:24:43,793 DEBUG : Unmounting /home/ubuntu/Data/tmp/vmbuilderYt3CgM/target/
2009-12-23 09:24:43,794 DEBUG : ['umount', '/home/ubuntu/Data/tmp/vmbuilderYt3CgM/target/']
2009-12-23 09:24:46,803 DEBUG : ['kpartx', '-d', '/home/ubuntu/Data/tmp/vmbuilderYt3CgM/disk0.img']
2009-12-23 09:24:46,813 DEBUG : loop deleted : /dev/loop2
2009-12-23 09:24:46,813 DEBUG : ['kpartx', '-d', '/home/ubuntu/Data/tmp/vmbuilderYt3CgM/disk0.img']
2009-12-23 09:24:46,819 DEBUG : ['rmdir', 'kvm-test-desktop3']
2009-12-23 09:24:46,822 DEBUG : ['rm', '-rf', '/home/ubuntu/Data/tmp/vmbuilderYt3CgM']
2009-12-23 09:24:46,885 INFO : rm: cannot remove `/home/ubuntu/Data/tmp/vmbuilderYt3CgM/root/proc/dri/0/vma': Operation not permitted
2009-12-23 09:24:46,886 INFO : rm: cannot remove `/home/ubuntu/Data/tmp/vmbuilderYt3CgM/root/proc/dri/0/bufs': Operation not permitted
.
.
.
===================

So, as suggested, I did run lsof:

$ sudo lsof -R /home/ubuntu/Data/tmp/vmbuilderYt3CgM/root/proc

COMMAND PID PPID USER FD TYPE DEVICE SIZE/OFF NODE NAME
dd 808 1 root 0r REG 0,3 0 4026531987 /proc/kmsg
lsof 21109 31948 root 3r DIR 0,3 0 1 /proc
lsof 21109 31948 root 6r DIR 0,3 0 1176729 /proc/21109/fd

So dd (with init as parent) is to blame.

Then:

$ ps ax | grep -w dd
4 0 808 1 20 0 8192 604 syslog Ss ? 0:00 dd bs=1 if=/proc/kmsg of=/var/run/rsyslog/kmsg

Kernel messages appear to not have finished flushing to disk.

I decided to try a sleep in this file

/usr/lib/python2.6/dist-packages/VMBuilder/plugins/ubuntu/dapper.py

Here

    def unmount_dev_proc(self):
        import time
        time.sleep(360)
        run_cmd('umount', '%s/dev/pts' % self.destdir)
        run_cmd('umount', '%s/dev' % self.destdir)
        run_cmd('umount', '%s/proc' % self.destdir)

But this did not help.