vmbuilder fails using tmpfs due to upstart restarting cron in the tmpfs

Bug #1008225 reported by Tokuko on 2012-06-03
16
This bug affects 2 people
Affects Status Importance Assigned to Milestone
vm-builder (Ubuntu)
High
Unassigned
Precise
High
Unassigned

Bug Description

===============================
SRU Justification:
1. Impact: simple vm creations fail
2. Development fix: use dpkg-divert to replace initctl with our stub, so that when usptart is installed it does not replace it with the real one
3. Stable fix: same as development fix
4. Test case:
 sudo vmbuilder kvm ubuntu -o -v --tmpfs 1536 --rootsize=4096M --swapsize=512M -d vm1
5. Regression potential: The behavior is changed for all target releases, so a regression is not impossible. However I don't see anything which looks gragile, and without this fix it is definitely broken.

===============================
root@tina ~ # vmbuilder kvm ubuntu -d /srv/kvm/b --tmpfs - -m 4096 --ip 192.168.0.18 --hostname b --user tokudan --pass abc123 --addpkg openssh-server --addpkg unattended-upgrades --addpkg acpid
2012-06-03 22:37:12,118 INFO : Mounting tmpfs under /tmp/tmptcTxLBtmpfs
2012-06-03 22:37:12,446 INFO : Calling hook: preflight_check
2012-06-03 22:37:12,449 INFO : Calling hook: set_defaults
2012-06-03 22:37:12,449 INFO : Calling hook: bootstrap
2012-06-03 22:38:13,765 INFO : Calling hook: configure_os
2012-06-03 22:38:18,088 INFO : update-alternatives: error: no alternatives for rsh.
2012-06-03 22:38:18,127 INFO : update-alternatives: error: no alternatives for rlogin.
2012-06-03 22:38:18,166 INFO : update-alternatives: error: no alternatives for rcp.
2012-06-03 22:38:18,420 INFO : Creating SSH2 RSA key; this may take some time ...
2012-06-03 22:38:18,474 INFO : Creating SSH2 DSA key; this may take some time ...
2012-06-03 22:38:18,517 INFO :
2012-06-03 22:38:18,517 INFO : Warning: Fake initctl called, doing nothing
2012-06-03 22:38:18,517 INFO :
2012-06-03 22:38:18,517 INFO : Warning: Fake initctl called, doing nothing
2012-06-03 22:38:18,624 INFO : update-rc.d: warning: unattended-upgrades start runlevel arguments (none) do not match LSB Default-Start values (0 6)
2012-06-03 22:38:18,624 INFO : update-rc.d: warning: unattended-upgrades stop runlevel arguments (0 6) do not match LSB Default-Stop values (none)
2012-06-03 22:38:19,287 INFO :
2012-06-03 22:38:19,287 INFO : Current default time zone: 'Etc/UTC'
2012-06-03 22:38:19,290 INFO : Local time is now: Sun Jun 3 20:38:19 UTC 2012.
2012-06-03 22:38:19,290 INFO : Universal Time is now: Sun Jun 3 20:38:19 UTC 2012.
2012-06-03 22:38:19,290 INFO :
Extracting templates from packages: 100%
2012-06-03 22:38:24,563 INFO :
2012-06-03 22:38:24,563 INFO : Current default time zone: 'Etc/UTC'
2012-06-03 22:38:24,565 INFO : Local time is now: Sun Jun 3 20:38:24 UTC 2012.
2012-06-03 22:38:24,565 INFO : Universal Time is now: Sun Jun 3 20:38:24 UTC 2012.
2012-06-03 22:38:24,565 INFO : Run 'dpkg-reconfigure tzdata' if you wish to change it.
2012-06-03 22:38:24,565 INFO :
2012-06-03 22:38:26,026 INFO : stop: Unknown instance:
2012-06-03 22:38:27,353 INFO : Updating certificates in /etc/ssl/certs... WARNING: Skipping duplicate certificate brasil.gov.br.pem
2012-06-03 22:38:27,353 INFO : 0 added, 1 removed; done.
2012-06-03 22:38:27,354 INFO : Running hooks in /etc/ca-certificates/update.d....done.
2012-06-03 22:38:27,768 INFO : restart: Unknown instance:
2012-06-03 22:38:27,861 INFO : start: Unknown parameter: JOB
2012-06-03 22:38:28,082 INFO : umount: /tmp/tmptcTxLBtmpfs/dev: device is busy.
2012-06-03 22:38:28,082 INFO : (In some cases useful info about processes that use
2012-06-03 22:38:28,083 INFO : the device is found by lsof(8) or fuser(1))
2012-06-03 22:38:28,083 INFO : Cleaning up
2012-06-03 22:38:28,083 ERROR : Process (['umount', '/tmp/tmptcTxLBtmpfs/dev']) returned 1. stdout: , stderr: umount: /tmp/tmptcTxLBtmpfs/dev: device is busy.
        (In some cases useful info about processes that use
         the device is found by lsof(8) or fuser(1))

2012-06-03 22:38:28,083 INFO : Unmounting tmpfs from /tmp/tmptcTxLBtmpfs
2012-06-03 22:38:28,086 INFO : umount: /tmp/tmptcTxLBtmpfs: device is busy.
2012-06-03 22:38:28,087 INFO : (In some cases useful info about processes that use
2012-06-03 22:38:28,087 INFO : 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 239, in main
    util.clean_up_tmpfs(tmpfs_mount_point)
  File "/usr/lib/python2.7/dist-packages/VMBuilder/util.py", line 199, in clean_up_tmpfs
    run_cmd(*umount_cmd)
  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', '-t', 'tmpfs', '/tmp/tmptcTxLBtmpfs']) returned 1. stdout: , stderr: umount: /tmp/tmptcTxLBtmpfs: device is busy.
        (In some cases useful info about processes that use
         the device is found by lsof(8) or fuser(1))

root@tina ~ # lsof | grep /tmp/tmptcTxLBtmpfs | awk '{print $1, $2}' | sort -u
cron 32720
root@tina ~ # ls -l /proc/32720/exe
lrwxrwxrwx 1 root root 0 Jun 3 22:40 /proc/32720/exe -> /tmp/tmptcTxLBtmpfs/usr/sbin/cron
root@tina ~ # kill -9 32720
root@tina ~ # tail /var/log/syslog
Jun 3 22:23:44 tina cron[12186]: (CRON) INFO (Skipping @reboot jobs -- not system startup)
Jun 3 22:23:44 tina kernel: [19691.313399] init: cron main process ended, respawning
Jun 3 22:38:27 tina cron[32719]: (CRON) INFO (pidfile fd = 3)
Jun 3 22:38:27 tina cron[32720]: (CRON) STARTUP (fork ok)
Jun 3 22:38:27 tina cron[32720]: (CRON) INFO (Running @reboot jobs)
Jun 3 22:40:35 tina kernel: [20701.709483] init: cron main process (32720) killed by KILL signal
Jun 3 22:40:35 tina kernel: [20701.709515] init: cron main process ended, respawning
Jun 3 22:40:35 tina cron[471]: (CRON) INFO (pidfile fd = 3)
Jun 3 22:40:35 tina cron[472]: (CRON) STARTUP (fork ok)
Jun 3 22:40:35 tina cron[472]: (CRON) INFO (Skipping @reboot jobs -- not system startup)
root@tina ~ # lsb_release -rd
Description: Ubuntu 12.04 LTS
Release: 12.04

Chuck Short (zulcss) wrote :

Which version of vmbuilder is this with?

Changed in vm-builder (Ubuntu):
status: New → Incomplete
Tokuko (launchpad-net-tokuko) wrote :

This is the version I'm using:
ii python-vm-builder 0.12.4+bzr477-0ubuntu1 VM builder

Serge Hallyn (serge-hallyn) wrote :

Interesting - this would also explain bug 879710.

Why would cron be being started? Does vmbuilder need to do a

cat > "$rootfs/partial-${arch}"/usr/sbin/policy-rc.d << EOF
#!/bin/sh
exit 101
EOF

(Stolen from the ubuntu lxc template and courtesy of stgraber)?

Changed in vm-builder (Ubuntu):
status: Incomplete → Confirmed
importance: Undecided → High
Alex Dehnert (adehnert) wrote :

It looks to me like the issue is that while vmbuilder moves away initctl to avoid starting any services, upstart (or maybe another init?) gets reinstalled, replacing the moved initctl. As a result, it leaks a cron invocation. (I'm not totally sure why the policy-rc.d change that's in the guest isn't working --- my assumption is that initctl is contacting Upstart outside the chroot over D-Bus, and that Upstart sees the hosts' /usr/sbin/policy-rc.d. I guess vmbuilder could stash something in that policy-rc.d, but that seems slightly messy.)

I've attached a patch that seems to allow me to build VMs running hardy, lucid, maverick, natty, oneiric, and precise (all amd64; I haven't tested other architectures). The earlier suites are no longer supported, so building those bails pretty quickly...

The attachment "lucid-vm.patch" of this bug report has been identified as being a patch. The ubuntu-reviewers team has been subscribed to the bug report so that they can review the patch. In the event that this is in fact not a patch you can resolve this situation by removing the tag 'patch' from the bug report and editing the attachment so that it is not flagged as a patch. Additionally, if you are member of the ubuntu-reviewers team please also unsubscribe the team from this bug report.

[This is an automated message performed by a Launchpad user owned by Brian Murray. Please contact him regarding any issues with the action taken in this bug report.]

tags: added: patch
Serge Hallyn (serge-hallyn) wrote :

Thanks, this patch seemed to work for me on quantal, for creating quantal and hardy vms.

Serge Hallyn (serge-hallyn) wrote :

Sorry, not quantal, but precise, lucid and hardy.

Launchpad Janitor (janitor) wrote :

This bug was fixed in the package vm-builder - 0.12.4+bzr480-0ubuntu1

---------------
vm-builder (0.12.4+bzr480-0ubuntu1) quantal; urgency=low

  * Patch from Alex Dehnert (adehnert) to fix tmpfs unmounting failure
    (LP: #1008225)
  * From Scott Moser: fix vmbuilder --version output (LP: #1003230)
 -- Serge Hallyn <email address hidden> Mon, 23 Jul 2012 23:10:58 -0500

Changed in vm-builder (Ubuntu):
status: Confirmed → Fix Released
Changed in vm-builder (Ubuntu Precise):
importance: Undecided → High
status: New → Triaged
assignee: nobody → Serge Hallyn (serge-hallyn)
description: updated
Changed in vm-builder (Ubuntu Precise):
status: Triaged → In Progress
assignee: Serge Hallyn (serge-hallyn) → nobody

Hello Tokuko, or anyone else affected,

Accepted vm-builder into precise-proposed. The package will build now and be available at http://launchpad.net/ubuntu/+source/vm-builder/0.12.4+bzr477-0ubuntu3 in a few hours, and then in the -proposed repository.

Please help us by testing this new package. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation how to enable and use -proposed. Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please change the bug tag from verification-needed to verification-done. If it does not, change the tag to verification-failed. In either case, details of your testing will help us make a better decision.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance!

Changed in vm-builder (Ubuntu Precise):
status: In Progress → Fix Committed
tags: added: verification-needed
Download full text (6.0 KiB)

alan@deep-thought:~$ sudo vmbuilder kvm ubuntu -o -v --tmpfs 1536 --rootsize=4096M --swapsize=512M -d vm1 --proxy=http://192.168.1.2:3128
2012-09-23 21:37:16,702 INFO : Mounting tmpfs under /tmp/tmpyXTs9ntmpfs
2012-09-23 21:37:16,705 INFO : Calling hook: preflight_check
2012-09-23 21:37:16,708 INFO : Calling hook: set_defaults
2012-09-23 21:37:16,708 INFO : Calling hook: bootstrap
2012-09-23 21:58:07,557 INFO : Calling hook: configure_os
2012-09-23 22:00:21,739 INFO :
2012-09-23 22:00:21,739 INFO : Current default time zone: 'Etc/UTC'
2012-09-23 22:00:21,740 INFO : Local time is now: Sun Sep 23 21:00:21 UTC 2012.
2012-09-23 22:00:21,740 INFO : Universal Time is now: Sun Sep 23 21:00:21 UTC 2012.
2012-09-23 22:00:21,740 INFO :
Extracting templates from packages: 100%
2012-09-23 22:14:46,150 INFO :
2012-09-23 22:14:46,151 INFO : Current default time zone: 'Etc/UTC'
2012-09-23 22:14:46,153 INFO : Local time is now: Sun Sep 23 21:14:46 UTC 2012.
2012-09-23 22:14:46,154 INFO : Universal Time is now: Sun Sep 23 21:14:46 UTC 2012.
2012-09-23 22:14:46,154 INFO : Run 'dpkg-reconfigure tzdata' if you wish to change it.
2012-09-23 22:14:46,154 INFO :
2012-09-23 22:14:50,928 INFO : Updating certificates in /etc/ssl/certs... WARNING: Skipping duplicate certificate brasil.gov.br.pem
2012-09-23 22:14:50,928 INFO : 0 added, 1 removed; done.
2012-09-23 22:14:50,933 INFO : Running hooks in /etc/ca-certificates/update.d....done.
2012-09-23 22:14:51,816 INFO :
2012-09-23 22:14:51,816 INFO : Warning: Fake initctl called, doing nothing
2012-09-23 22:15:13,523 INFO : Cleaning up
2012-09-23 22:15:13,523 INFO : Calling hook: preflight_check
2012-09-23 22:15:13,523 INFO : Calling hook: configure_networking
2012-09-23 22:15:13,533 INFO : Calling hook: configure_mounting
2012-09-23 22:15:13,538 INFO : Calling hook: mount_partitions
2012-09-23 22:15:13,539 INFO : Mounting target filesystems
2012-09-23 22:15:13,539 INFO : Creating disk image: "/tmp/tmp83B_ke" of size: 4608MB
2012-09-23 22:15:13,551 INFO : Adding partition table to disk image: /tmp/tmp83B_ke
2012-09-23 22:15:13,899 INFO : Adding type 4 partition to disk image: /tmp/tmp83B_ke
2012-09-23 22:15:13,899 INFO : Partition at beginning of disk - reserving first cylinder
2012-09-23 22:15:14,303 INFO : Adding type 3 partition to disk image: /tmp/tmp83B_ke
2012-09-23 22:15:14,313 INFO : [0] ../../libparted/filesys.c:148 (ped_file_system_type_get): File system alias linux-swap(new) is deprecated
2012-09-23 22:15:14,607 INFO : Creating loop devices corresponding to the created partitions
2012-09-23 22:15:14,620 INFO : Creating file systems
2012-09-23 22:15:14,634 INFO : mke2fs 1.42 (29-Nov-2011)
2012-09-23 22:15:15,033 INFO : mkswap: /dev/mapper/loop0p2: warning: don't erase bootbits sectors
2012-09-23 22:15:15,033 INFO : on whole disk. Use -f to force.
2012-09-23 22:15:17,087 INFO : Calling hook: install_bootloader
2012-09-23 22:16:24,188 INFO : Searching for GRUB installation directory ... found: /boot/grub
2012-09-23 22:16:24,216 INFO : Searching for default file ... Gen...

Read more...

tags: added: verification-done
removed: verification-needed
tags: added: verification-needed
removed: verification-done

Oops, left comment on wrong bug, should have left this on bug 966944. Sorry for the noise.

Jarl-p (jarl-p) wrote :

I had started getting this error with chroot/dev not unmounting cleanly, caused by the same issue (you could see the extra cron processes running afterwards). This patch looks to have fixed it for me.

Brian Murray (brian-murray) wrote :

Jarl-p - do you mean that you are running the version of the package from -proposed and that fixes it for you? Or did you patch your code locally? If you are in fact using the version of vm-builder from -proposed it would be great if you could change the tag from verification-needed to verification-done.

Brian Murray (brian-murray) wrote :

The verification of this was trivial enough that I did it myself.

Using python-vm-builder version 0.12.4+bzr477-0ubuntu3 from precise-proposed I did not experience this crash, and I was able to reproduce the crash with the previous version of python-vm-builder (0ubuntu1).

tags: added: verification-done
removed: verification-needed

The verification of this Stable Release Update has completed successfully and the package has now been released to -updates. Subsequently, the Ubuntu Stable Release Updates Team is being unsubscribed and will not receive messages about this bug report. In the event that you encounter a regression using the package from -updates please report a new bug using ubuntu-bug and tag the bug report regression-update so we can easily find any regresssions.

Launchpad Janitor (janitor) wrote :

This bug was fixed in the package vm-builder - 0.12.4+bzr477-0ubuntu3

---------------
vm-builder (0.12.4+bzr477-0ubuntu3) precise-proposed; urgency=low

  [ Alex Dehnert ]
  * fix tmpfs unmounting failure (LP: #1008225)

vm-builder (0.12.4+bzr477-0ubuntu2) precise-proposed; urgency=low

  [ Yoann Dubreuil ]
  * Fix proxy support: set up apt proxies before writing sources.list.
    (LP: #966944)
 -- Serge Hallyn <email address hidden> Mon, 06 Aug 2012 16:06:51 -0500

Changed in vm-builder (Ubuntu Precise):
status: Fix Committed → Fix Released
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers