umount of temporary devfs fails

[Max Brustkern]

Often when I'm trying to run vmbuilder, the umount of /dev in the temporary directory will fail, causing the process to stop. When I have looked into it so far, it appears that cron processes run by root are accessing files under the temporary /dev directory. Is there some way to mitigate this? My output follows:

ubuntu@aldebaran:~/maxvm$ sudo vmbuilder kvm ubuntu
2012-03-27 17:48:55,733 INFO : Calling hook: preflight_check
2012-03-27 17:48:55,741 INFO : Calling hook: set_defaults
2012-03-27 17:48:55,742 INFO : Calling hook: bootstrap
2012-03-27 17:52:55,906 INFO : Calling hook: configure_os
2012-03-27 17:53:05,168 INFO :
2012-03-27 17:53:05,169 INFO : Current default time zone: 'Etc/UTC'
2012-03-27 17:53:05,173 INFO : Local time is now: Tue Mar 27 17:53:05 UTC 2012.
2012-03-27 17:53:05,173 INFO : Universal Time is now: Tue Mar 27 17:53:05 UTC 2012.
2012-03-27 17:53:05,174 INFO :
Extracting templates from packages: 100%
2012-03-27 17:53:46,817 INFO :
2012-03-27 17:53:46,818 INFO : Current default time zone: 'Etc/UTC'
2012-03-27 17:53:46,822 INFO : Local time is now: Tue Mar 27 17:53:46 UTC 2012.
2012-03-27 17:53:46,822 INFO : Universal Time is now: Tue Mar 27 17:53:46 UTC 2012.
2012-03-27 17:53:46,823 INFO : Run 'dpkg-reconfigure tzdata' if you wish to change it.
2012-03-27 17:53:46,823 INFO :
2012-03-27 17:53:51,044 INFO : stop: Unknown instance:
2012-03-27 17:53:54,484 INFO : Updating certificates in /etc/ssl/certs... WARNING: Skipping duplicate certificate ca-certificates.crt
2012-03-27 17:53:55,020 INFO : 0 added, 1 removed; done.
2012-03-27 17:53:55,022 INFO : Running hooks in /etc/ca-certificates/update.d....done.
2012-03-27 17:53:56,101 INFO : restart: Unknown instance:
2012-03-27 17:53:56,312 INFO : start: Unknown parameter: JOB
2012-03-27 17:53:56,961 INFO : umount: /tmp/tmpGmrfKV/dev: device is busy.
2012-03-27 17:53:56,961 INFO : (In some cases useful info about processes that use
2012-03-27 17:53:56,962 INFO : the device is found by lsof(8) or fuser(1))
2012-03-27 17:53:56,962 INFO : Cleaning up
2012-03-27 17:53:56,962 ERROR : Process (['umount', '/tmp/tmpGmrfKV/dev']) returned 1. stdout: , stderr: umount: /tmp/tmpGmrfKV/dev: device is busy.
        (In some cases useful info about processes that use
         the device is found by lsof(8) or fuser(1))

Traceback (most recent call last):
  File "/usr/bin/vmbuilder", line 24, in <module>
    cli.main()
  File "/usr/lib/python2.7/dist-packages/VMBuilder/contrib/cli.py", line 216, in main
    distro.build_chroot()
  File "/usr/lib/python2.7/dist-packages/VMBuilder/distro.py", line 84, in build_chroot
    self.call_hooks('configure_os')
  File "/usr/lib/python2.7/dist-packages/VMBuilder/distro.py", line 67, in call_hooks
    call_hooks(self, *args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/VMBuilder/util.py", line 165, in call_hooks
    getattr(context, func, log_no_such_method)(*args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/VMBuilder/plugins/ubuntu/distro.py", line 156, in configure_os
    self.suite.unmount_dev()
  File "/usr/lib/python2.7/dist-packages/VMBuilder/plugins/ubuntu/dapper.py", line 118, in unmount_dev
    run_cmd('umount', '%s/dev' % self.context.chroot_dir)
  File "/usr/lib/python2.7/dist-packages/VMBuilder/util.py", line 120, in run_cmd
    raise VMBuilderException, "Process (%s) returned %d. stdout: %s, stderr: %s" % (args.__repr__(), status, mystdout.buf, mystderr.buf)
VMBuilder.exception.VMBuilderException: Process (['umount', '/tmp/tmpGmrfKV/dev']) returned 1. stdout: , stderr: umount: /tmp/tmpGmrfKV/dev: device is busy.
        (In some cases useful info about processes that use
         the device is found by lsof(8) or fuser(1))

[David Rasch (rasch)]

I too am experiencing thigs bug on oneiric trying to build a lucid guest with a command line like:

vmbuilder kvm ubuntu --suite lucid --arch i386 -o --libvirt qemu:///system --ip 172.29.5.50 --dns 172.29.5.2 --bridge br0 --user system --pass system

On my system, it not only gives this error but it's actually broken out of the chroot jail and I cannot remove the /tmp/tmp* dir because the host kernel is now using it somehow.

for example:
[11068.758303] init: /tmp/tmpWi7L20/etc/init: Configuration directory deleted

2012-04-02 19:59 DEBUG : Output from template '/etc/vmbuilder/ubuntu/sources.list.tmpl': deb http://archive.ubuntu.com/ubuntu lucid main restricted universe
deb http://archive.ubuntu.com/ubuntu lucid-updates main restricted universe
deb http://security.ubuntu.com/ubuntu lucid-security main restricted universe

2012-04-02 19:59 DEBUG : ['chroot', '/tmp/tmpjwPN8y', 'apt-get', 'update']
2012-04-02 19:59 DEBUG : Hit http://security.ubuntu.com lucid-security Release.gpg
2012-04-02 19:59 DEBUG : Hit http://archive.ubuntu.com lucid Release.gpg
2012-04-02 19:59 DEBUG : Hit http://archive.ubuntu.com lucid-updates Release.gpg
2012-04-02 19:59 DEBUG : Hit http://security.ubuntu.com lucid-security Release
2012-04-02 19:59 DEBUG : Hit http://archive.ubuntu.com lucid Release
2012-04-02 19:59 DEBUG : Hit http://security.ubuntu.com lucid-security/main Packages
2012-04-02 19:59 DEBUG : Hit http://archive.ubuntu.com lucid-updates Release
2012-04-02 19:59 DEBUG : Hit http://security.ubuntu.com lucid-security/restricted Packages
2012-04-02 19:59 DEBUG : Hit http://security.ubuntu.com lucid-security/universe Packages
2012-04-02 19:59 DEBUG : Hit http://archive.ubuntu.com lucid/main Packages
2012-04-02 19:59 DEBUG : Hit http://archive.ubuntu.com lucid/restricted Packages
2012-04-02 19:59 DEBUG : Hit http://archive.ubuntu.com lucid/universe Packages
2012-04-02 19:59 DEBUG : Hit http://archive.ubuntu.com lucid-updates/main Packages
2012-04-02 19:59 DEBUG : Hit http://archive.ubuntu.com lucid-updates/restricted Packages
2012-04-02 19:59 DEBUG : Hit http://archive.ubuntu.com lucid-updates/universe Packages
2012-04-02 19:59 DEBUG : Reading package lists...
2012-04-02 19:59 DEBUG : ['chroot', '/tmp/tmpjwPN8y', 'apt-get', 'clean']
2012-04-02 19:59 DEBUG : ['umount', '/tmp/tmpjwPN8y/proc']
2012-04-02 19:59 DEBUG : ['umount', '/tmp/tmpjwPN8y/dev/pts']
2012-04-02 19:59 DEBUG : ['umount', '/tmp/tmpjwPN8y/dev']
2012-04-02 19:59 INFO : umount: /tmp/tmpjwPN8y/dev: device is busy.
2012-04-02 19:59 INFO : (In some cases useful info about processes that use
2012-04-02 19:59 INFO : the device is found by lsof(8) or fuser(1))
2012-04-02 19:59 INFO : Cleaning up
2012-04-02 19:59 ERROR : Process (['umount', '/tmp/tmpjwPN8y/dev']) returned 1. stdout: , stderr: umount: /tmp/tmpjwPN8y/dev: device is busy.

[David Rasch (rasch)]

and a list of open files:

cron 22520 root cwd DIR 9,0 4096 262115 /tmp/tmpjwPN8y/var/spool/cron
cron 22520 root rtd DIR 9,0 4096 246512 /tmp/tmpjwPN8y
cron 22520 root txt REG 9,0 35800 248797 /tmp/tmpjwPN8y/usr/sbin/cron
cron 22520 root mem REG 9,0 42572 262561 /tmp/tmpjwPN8y/lib/tls/i686/cmov/libnss_files-2.11.1.so
cron 22520 root mem REG 9,0 34408 262630 /tmp/tmpjwPN8y/lib/tls/i686/cmov/libnss_nis-2.11.1.so
cron 22520 root mem REG 9,0 79676 262491 /tmp/tmpjwPN8y/lib/tls/i686/cmov/libnsl-2.11.1.so
cron 22520 root mem REG 9,0 30496 262629 /tmp/tmpjwPN8y/lib/tls/i686/cmov/libnss_compat-2.11.1.so
cron 22520 root mem REG 9,0 38360 262509 /tmp/tmpjwPN8y/lib/tls/i686/cmov/libcrypt-2.11.1.so
cron 22520 root mem REG 9,0 9736 262510 /tmp/tmpjwPN8y/lib/tls/i686/cmov/libdl-2.11.1.so
cron 22520 root mem REG 9,0 1405508 262564 /tmp/tmpjwPN8y/lib/tls/i686/cmov/libc-2.11.1.so
cron 22520 root mem REG 9,0 104148 247975 /tmp/tmpjwPN8y/lib/libselinux.so.1
cron 22520 root mem REG 9,0 46684 248358 /tmp/tmpjwPN8y/lib/libpam.so.0.82.2
cron 22520 root mem REG 9,0 113964 247512 /tmp/tmpjwPN8y/lib/ld-2.11.1.so
cron 22520 root 0r CHR 1,3 0t0 4277 /tmp/tmpjwPN8y/dev/null
cron 22520 root 1w CHR 1,3 0t0 4277 /tmp/tmpjwPN8y/dev/null
cron 22520 root 2w CHR 1,3 0t0 4277 /tmp/tmpjwPN8y/dev/null
cron 22520 root 3u REG 9,0 6 246712 /tmp/tmpjwPN8y/var/run/crond.pid

[David Rasch (rasch)]

May be related to: https://bugs.launchpad.net/ubuntu/+source/upstart/+bug/592114

[Chris Samaritoni (9e9o1ko8b2f5xp-fvlbw-0zxvj9hhx1hzo5)]

I'm running into this exact same problem. I'm running the latest version of the precise.

It was working about two weeks or so ago, but yesterday I did and apt-get upgrade on the server I'm running and now can't build new VMs on it. There were so many packages updated I'm scratching my head trying to figure out which one would have caused it.

I noticed as well, killing the cron process doesn't help it immediately restarts a new one and keeps those files open. Does anyone know what would control that cron process restarting?

[faifo (luong-la)]

I got same problem...

2012-04-06 15:01:51,627 INFO : Calling hook: preflight_check
2012-04-06 15:01:51,642 INFO : Calling hook: set_defaults
2012-04-06 15:01:51,644 INFO : Calling hook: bootstrap
2012-04-06 15:10:17,814 INFO : Calling hook: configure_os
2012-04-06 15:10:29,295 INFO :
2012-04-06 15:10:29,296 INFO : Current default time zone: 'Etc/UTC'
2012-04-06 15:10:29,300 INFO : Local time is now: Fri Apr 6 20:10:29 UTC 2012.
2012-04-06 15:10:29,301 INFO : Universal Time is now: Fri Apr 6 20:10:29 UTC 2012.
2012-04-06 15:10:29,302 INFO :
Extracting templates from packages: 100%
2012-04-06 15:11:14,237 INFO :
2012-04-06 15:11:14,238 INFO : Current default time zone: 'Etc/UTC'
2012-04-06 15:11:14,243 INFO : Local time is now: Fri Apr 6 20:11:14 UTC 2012.
2012-04-06 15:11:14,248 INFO : Universal Time is now: Fri Apr 6 20:11:14 UTC 2012.
2012-04-06 15:11:14,248 INFO : Run 'dpkg-reconfigure tzdata' if you wish to change it.
2012-04-06 15:11:14,249 INFO :
2012-04-06 15:12:15,274 INFO : stop: Unknown instance:
2012-04-06 15:12:39,350 INFO : Updating certificates in /etc/ssl/certs... WARNING: Skipping duplicate certificate brasil.gov.br.pem
2012-04-06 15:12:39,484 INFO : 0 added, 1 removed; done.
2012-04-06 15:12:39,500 INFO : Running hooks in /etc/ca-certificates/update.d....done.
2012-04-06 15:12:48,388 INFO : restart: Unknown instance:
2012-04-06 15:12:49,261 INFO : start: Unknown parameter: JOB
2012-04-06 15:12:51,128 INFO : umount: /tmp/tmp206_J9/dev: device is busy.
2012-04-06 15:12:51,129 INFO : (In some cases useful info about processes that use
2012-04-06 15:12:51,129 INFO : the device is found by lsof(8) or fuser(1))
2012-04-06 15:12:51,130 INFO : Cleaning up
2012-04-06 15:12:51,130 ERROR : Process (['umount', '/tmp/tmp206_J9/dev']) returned 1. stdout: , stderr: umount: /tmp/tmp206_J9/dev: device is busy.
        (In some cases useful info about processes that use
         the device is found by lsof(8) or fuser(1))

Traceback (most recent call last):
  File "/usr/bin/vmbuilder", line 24, in <module>
    cli.main()
  File "/usr/lib/python2.7/dist-packages/VMBuilder/contrib/cli.py", line 216, in main
    distro.build_chroot()
  File "/usr/lib/python2.7/dist-packages/VMBuilder/distro.py", line 84, in build_chroot
    self.call_hooks('configure_os')
  File "/usr/lib/python2.7/dist-packages/VMBuilder/distro.py", line 67, in call_hooks
    call_hooks(self, *args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/VMBuilder/util.py", line 165, in call_hooks
    getattr(context, func, log_no_such_method)(*args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/VMBuilder/plugins/ubuntu/distro.py", line 155, in configure_os
    self.suite.unmount_dev()
  File "/usr/lib/python2.7/dist-packages/VMBuilder/plugins/ubuntu/dapper.py", line 118, in unmount_dev
    run_cmd('umount', '%s/dev' % self.context.chroot_dir)
  File "/usr/lib/python2.7/dist-packages/VMBuilder/util.py", line 120, in run_cmd
    raise VMBuilderException, "Process (%s) returned %d. stdout: %s, stderr: %s" % (args.__repr__(), status, mystdout.buf, mystderr.buf)
VMBuil...

[Andreas Haßfeld (8nd0ecy)]

Same here when creating a lucid guest on a natty kvm host. This seems to be related to cron in the new VM. I worked around this issue by using vmbuilder's option "--removepkg=cron" to prevent cron from being installed inside the new VM. This worked as expected and I installed cron afterwards in the running VM.

Question: is this a bug in natty's vmbuilder/upstart or in lucid's cron/upstart?

[Andreas Haßfeld (8nd0ecy)]

BTW: stopping cron on the natty kvm host using "service cron stop" before starting vmbuilder did not prevent the new cron process from starting and locking the /tmp/.../dev/ folder.

[Chris Samaritoni (9e9o1ko8b2f5xp-fvlbw-0zxvj9hhx1hzo5)]

Thanks Andreas! the "removepkg=cron" option does allow me to create new VMs successfully again

The interesting thing is I know that in the past cron was not installed by default, when I run the vmbuilder with minimal options. And now I guess it is being installed. I guess something recently changed with what is included in the default install set of packages, to now include the "cron" package. I'm guessing the cron package is not correctly formated to support installing it but not running it or it's not handling being stopped during the setup, which is what I noticed if you kill the process it immediately restarts.

[Chris Samaritoni (9e9o1ko8b2f5xp-fvlbw-0zxvj9hhx1hzo5)]

Just for a followup since 12.04 is now out. I'm still seeing this issue on a 12.04 hypervisor and creating a 10.04 VM with vmbuilder, but if you create a 12.04 VM it builds fine. In the case of a 10.04 VM, I have to include the "removepkg=cron" option and 10.04 then builds correctly.

[spidernik84 (alexander-rilik)]

I can confirm the issue as well, for what is worth :)
Any estimate on the fix?

[Simon Eisenmann (longsleep)]

This is major pain in the ass and it's a shame that this is still not resolved with 12.04.1 out.

[Steffen H. (shulegaa)]

This bug just hit me as well using 12.04.1. The longer running the vmbuilder command, the more likely it seems to be to run into this bug (as one might expect). Bummer!

[Steffen H. (shulegaa)]

Actually, the error message is the same but the actual trigger was totally unrelated and innocuous. In my case, this error message occurred when the vmbuilder command line used a -c <file.cfg> that did not exist! So while this isn't the least bit helpful as an error message, it might help others to examine the command lines (especially if they are creating multiple VMs and cutting-and-pasting commands ;-). It may also help to carefully review the contents of the -c <file.cfg>.

For what it's worth, I just happen to be using this particular command line when I encountered this VERY MISLEADING error.

     vmbuilder kvm ubuntu --part=./vmbuilder.partition -c vrootca.cfg

Once I created the referenced vrootca.cfg, vmbuilder completed without error.