[jaunty] ubuntu-vm-builder crashed with ioctl in create()

[Jamie Strandboge]

This error occurred after I started creating VMs after recently rebooting. I did not have any loopback filesystems mounted at the time (other than anything ubuntu-vm-builder does).

ProblemType: Crash
Architecture: amd64
DistroRelease: Ubuntu 9.04
ExecutablePath: /usr/bin/ubuntu-vm-builder
InterpreterPath: /usr/bin/python2.6
Package: ubuntu-vm-builder 0.10-0ubuntu1
PackageArchitecture: all
ProcAttrCurrent: unconfined
ProcCmdline: /usr/bin/python /usr/bin/ubuntu-vm-builder kvm jaunty -d /srv/vms/kvm/clean-jaunty-amd64 --hostname clean-jaunty-amd64 --mirror http://192.168.122.1/ubuntu --rootsize 4096 --swapsize=1024 --kernel-flavour generic --components main,restricted,universe,multiverse --libvirt qemu:///system -a amd64 --exec /tmp/tmp.FBwnAVxwIe --ssh-key /home/jamie/.ssh/id_rsa.pub --user jamie --mem 384 --debug
ProcEnviron:
 PATH=(custom, no user)
 LANG=en_US.UTF-8
 SHELL=/bin/bash
PythonArgs: ['/usr/bin/ubuntu-vm-builder', 'kvm', 'jaunty', '-d', '/srv/vms/kvm/clean-jaunty-amd64', '--hostname', 'clean-jaunty-amd64', '--mirror', 'http://192.168.122.1/ubuntu', '--rootsize', '4096', '--swapsize=1024', '--kernel-flavour', 'generic', '--components', 'main,restricted,universe,multiverse', '--libvirt', 'qemu:///system', '-a', 'amd64', '--exec', '/tmp/tmp.FBwnAVxwIe', '--ssh-key', '/home/jamie/.ssh/id_rsa.pub', '--user', 'jamie', '--mem', '384', '--debug']
SourcePackage: vm-builder
Title: ubuntu-vm-builder crashed with ioctl in create()
Uname: Linux 2.6.28-8-generic x86_64
UserGroups:

[Jamie Strandboge (jdstrand)]

This is not guest os specific-- I just had the same thing trying to create a Hardy guest with the same arguments.

[Jamie Strandboge (jdstrand)]

I noticed a bunch of loopback files were not removed after several runs:
$ sudo losetup -a
/dev/loop0: [0802]:1712191 (/tmp/vmbuilderoz9Ae3/disk0.img)
/dev/loop1: [0802]:1712192 (/tmp/vmbuilderZ25Vlg/disk0.img)
/dev/loop2: [0802]:1712199 (/tmp/vmbuilderMYw8D9/disk0.img)
/dev/loop3: [0802]:1712202 (/tmp/vmbuildertNVvQu/disk0.img)
/dev/loop4: [0802]:1712205 (/tmp/vmbuilderdfXyav/disk0.img)
/dev/loop5: [0802]:1712208 (/tmp/vmbuilderPyYKWF/disk0.img)

So then I tried to see why:
$ sudo lsof | grep loop[0-5]
lsof: WARNING: can't stat() fuse.gvfs-fuse-daemon file system /home/jamie/.gvfs
      Output information may be incomplete.
loop5 1831 root cwd DIR 8,2 4096 2 /
loop5 1831 root rtd DIR 8,2 4096 2 /
loop5 1831 root txt unknown /proc/1831/exe
loop3 16839 root cwd DIR 8,2 4096 2 /
loop3 16839 root rtd DIR 8,2 4096 2 /
loop3 16839 root txt unknown /proc/16839/exe
loop0 17985 root cwd DIR 8,2 4096 2 /
loop0 17985 root rtd DIR 8,2 4096 2 /
loop0 17985 root txt unknown /proc/17985/exe
loop2 22974 root cwd DIR 8,2 4096 2 /
loop2 22974 root rtd DIR 8,2 4096 2 /
loop2 22974 root txt unknown /proc/22974/exe
loop4 26281 root cwd DIR 8,2 4096 2 /
loop4 26281 root rtd DIR 8,2 4096 2 /
loop4 26281 root txt unknown /proc/26281/exe
loop1 32714 root cwd DIR 8,2 4096 2 /
loop1 32714 root rtd DIR 8,2 4096 2 /
loop1 32714 root txt unknown /proc/32714/exe

[Marc Deslauriers (mdeslaur)]

I'm seeing this:

2009-03-17 14:05:45,658 DEBUG loop deleted : /dev/loop0
2009-03-17 14:05:45,659 DEBUG ['rmdir', '/home/mdeslaur/machines/foo-hardy-amd64']
2009-03-17 14:05:45,662 DEBUG ['rm', '-rf', '/tmp/vmbuilderID1u60']
Traceback (most recent call last):
  File "/usr/bin/ubuntu-vm-builder", line 29, in <module>
    VMBuilder.run()
  File "/usr/lib/python2.6/dist-packages/VMBuilder/__init__.py", line 66, in run
    frontend.run()
  File "/usr/lib/python2.6/dist-packages/VMBuilder/plugins/cli/__init__.py", line 67, in run
    vm.create()
  File "/usr/lib/python2.6/dist-packages/VMBuilder/vm.py", line 469, in create
    raise e
VMBuilder.exception.VMBuilderException: Process (['kpartx', '-d', '/tmp/vmbuilderID1u60/disk0.img']) returned 1. stdout: , stderr: device-mapper: remove ioctl failed: Device or resource busy
ioctl: LOOP_CLR_FD: Device or resource busy

[Jamie Strandboge (jdstrand)]

I just tried to create a hardy VM and five times in a row got (same as attached traceback):
Traceback (most recent call last):
  File "/usr/bin/ubuntu-vm-builder", line 29, in <module>
    VMBuilder.run()
  File "/usr/lib/python2.6/dist-packages/VMBuilder/__init__.py", line 66, in run
    frontend.run()
  File "/usr/lib/python2.6/dist-packages/VMBuilder/plugins/cli/__init__.py", line 67, in run
    vm.create()
  File "/usr/lib/python2.6/dist-packages/VMBuilder/vm.py", line 469, in create
    raise e
VMBuilder.exception.VMBuilderException: Process (['kpartx', '-d', '/tmp/vmbuilderTExwaL/disk0.img']) returned 1. stdout: , stderr: device-mapper: remove ioctl failed: Device or resource busy
ioctl: LOOP_CLR_FD: Device or resource busy

[Jamie Strandboge (jdstrand)]

Attached is a patch that should address this issue. Basically, it will try up to three times to unmount the disk, rather than failing on the first time. Example output from an attempt that would have previously failed:
...
2009-03-24 00:42:12,075 INFO Unmounting target filesystem
2009-03-24 00:42:12,076 DEBUG Unmounting /tmp/vmbuilderYGTk5J/target/
2009-03-24 00:42:12,076 DEBUG ['umount', '/tmp/vmbuilderYGTk5J/target/']
2009-03-24 00:42:12,488 INFO Attempting to unmount disk '/tmp/vmbuilderYGTk5J/disk0.img'
2009-03-24 00:42:12,489 DEBUG ['kpartx', '-d', '/tmp/vmbuilderYGTk5J/disk0.img']
2009-03-24 00:42:12,502 INFO device-mapper: remove ioctl failed: Device or resource busy
2009-03-24 00:42:12,504 INFO ioctl: LOOP_CLR_FD: Device or resource busy
2009-03-24 00:42:12,504 INFO Failed to unmount disk '/tmp/vmbuilderYGTk5J/disk0.img'
2009-03-24 00:42:15,507 INFO Attempting to unmount disk '/tmp/vmbuilderYGTk5J/disk0.img'
2009-03-24 00:42:15,507 DEBUG ['kpartx', '-d', '/tmp/vmbuilderYGTk5J/disk0.img']
2009-03-24 00:42:15,519 DEBUG loop deleted : /dev/loop6
2009-03-24 00:42:15,520 INFO Converting /tmp/vmbuilderYGTk5J/disk0.img to qcow2, format debian-kvm/disk0.qcow2
...

[Jamie Strandboge (jdstrand)]

Here is the correct patch.

[Jamie Strandboge (jdstrand)]

Here is an updated patch that does the retries at a lower level. This will likely help with bug #342239 as well.

[Jamie Strandboge (jdstrand)]

Removed the two previous patches and added reference to my bzr branch with the final workaround.

[Bryan McLellan (btm)]

Building from jstrand's bzr branch works for me on jaunty (aside from separate build issues in Bug 354849).

[Jamie Strandboge (jdstrand)]

IMO using the workaround in Jaunty at this point is preferable to the regression. Perhaps apply it now and remove it when a fix is found in Karmic?

[Brandon Konkle (brandon-konkle)]

I can confirm that I had this issue with the Jaunty Server Beta, also. After making jstrand's changes to disk.py, the creation of the VM went smoothly. Thanks, Jamie!

[Jamie Strandboge (jdstrand)]

Attached is the debdiff used in the 0.10-0ubuntu2 upload. It also necessarily fixes bug #354849

[Launchpad Janitor (janitor)]

This bug was fixed in the package vm-builder - 0.10-0ubuntu2

---------------
vm-builder (0.10-0ubuntu2) jaunty; urgency=low

  * fix traceback due to kpartx failure (LP: #342359)
    - VMBuilder/disk.py: sleep a few seconds to give the loopback devices
      a chance to settle down, then try to unmount. If it fails, try a few
      more times and if still fails, error out as before
  * fix FTBFS due to python2.6 transition (LP: #354849)
    - debian/python-vm-builder-ec2.install: use python2.6/dist-packages path
    - debian/python-vm-builder.install: use python2.6/dist-packages path

 -- Jamie Strandboge <email address hidden> Fri, 10 Apr 2009 10:23:19 -0500