Fails to unmount /proc

[sebastinas]

When trying to create a jessie image bootstrap-vz fails at the end with:

[1923699.63694] DEBUG: Executing: umount /opt/bootstrap-vz/88d408db/root/proc
[1923702.44503] ERROR: umount: /opt/bootstrap-vz/88d408db/root/proc: target is busy
[1923702.60501] ERROR: (In some cases useful info about processes that
[1923702.66891] ERROR: use the device is found by lsof(8) or fuser(1).)

The problem seems to be that binfmt_misc is still mounted /opt/bootstrap-vz/88d408db/root/proc/sys/fs/binfmt_misc at this point. I'm not sure why binfmt_misc is mounted. The only occurrence I could find is in systemd automount targets.

This is my manifest:

---
name: ITS-2016-{system.release}-{system.architecture}-{%y}{%m}{%d}

provider:
  name: virtualbox
  guest_additions: /usr/share/virtualbox/VBoxGuestAdditions.iso

bootstrapper:
  workspace: /opt/bootstrap-vz

image:
  name: debian-{system.release}-{system.architecture}-{%y}{%m}{%d}
  description: Debian {system.release} {system.architecture}

system:
  release: jessie
  architecture: amd64
  bootloader: grub
  charmap: UTF-8
  hostname: its-2016
  locale: en_US
  timezone: Europe/Vienna

volume:
  backing: vmdk
  partitions:
    type: msdos
    root:
      filesystem: ext4
      size: 10GB

packages:
  mirror: http://httpredir.debian.org/debian

  sources:
    backports:
      - deb http://httpredir.debian.org/debian jessie-backports main

  install_standard: false
  install:
  - cmake
  - debian-goodies
  - eclipse-cdt
  - g++
  - gdb
  - git
  - gitg
  - gtk3-engines-oxygen
  - htop
  - meld
  - task-xfce-desktop
  - valgrind
  - zsh
  - doxygen
  - octave

plugins:
  admin_user:
    username: its2016

  minimize_size:
    zerofree: true

  unattended_upgrades:
    update_interval: 3
    upgrade_interval: 3

    # “Almost never” download non-security updates
    download_interval: 1000

Please let me know if you need any other info.

[nbraud]

@andsens I tried to reproduce on current master (from a Stretch box) and failed.
I will likely investigate further, as @sebastinas is a coworker :-)

[sebastinas]

Here is a full log from a run that fails while unmounting /proc: https://gist.github.com/sebastinas/234c88c756b5dc626e20. I've seen this problem with 0.9.9 and current git master on a Ubuntu 15.10 and an update Debian unstable system.

On both systems I have:

$ mount | grep binfmt_misc
systemd-1 on /proc/sys/fs/binfmt_misc type autofs (rw,relatime,fd=31,pgrp=1,timeout=0,minproto=5,maxproto=5,direct)
binfmt_misc on /proc/sys/fs/binfmt_misc type binfmt_misc (rw,relatime)

Maybe these mounts leak into the chroot.

[andsens]

This is very curious. I wonder how it gets mounted.
Could you try to raise Exception('blah') here while running with --pause-on-error? This way you can examine the state of the chroot just before the special devices are mounted. Try running mount --types proc none /path/to/proc/in/chroot and check out if binfmt_misc automatically gets mounted as well.
Regardless, I have a feeling that #294 might help us get out of this situation :-)

[sebastinas]

It appears to happen at some later point. This is what I got when manually mounting proc:

% mount | grep 442
/dev/mapper/nbd0p1 on /opt/bootstrap-vz/4424e1c0/root type ext4 (rw,relatime,data=ordered)
% sudo mount --types proc none /opt/bootstrap-vz/4424e1c0/root/proc
% mount | grep 442
/dev/mapper/nbd0p1 on /opt/bootstrap-vz/4424e1c0/root type ext4 (rw,relatime,data=ordered)
none on /opt/bootstrap-vz/4424e1c0/root/proc type proc (rw,relatime)

[nbraud]

@sebastinas Could you run ls -Al /etc/binfmt.d /run/binfmt.d /usr/lib/binfmt.d on the host?
The difference between our boxes might be that you have packages installed that registered bin formats.

[nbraud]

@sebastinas Also, I rebased my branch https://github.com/nbraud/bootstrap-vz/tree/special-devices, so you can try with it (that's the branch behind #294)

[andsens]

Argh! You were like.. 10 minutes too early. I just pushed a bunch of stuff that helps a lot with testing properly (dry runs, docs building etc.). I was about to test your branch when I went down the rabbit hole because things like the docs were breaking, and a merge had killed the docker provider.

[nbraud]

@andsens You are in luck, I'm still woken up.
I seem to have a knack lately to wake up in the middle of the night and find important mails, new commits, ...

[andsens]

Haha. Nice :-)
But.. wth? https://travis-ci.org/andsens/bootstrap-vz/builds/113546634
I don't think it's your fault, seems like som kind of fluke.

EDIT: Nope, restarted the build, same error. Is it because you are doing some funky stuff with hexadecimals?

[sebastinas]

@nbraud The special-devices branch fails with a completely different error:

[119.826078415] DEBUG: Loading provider virtualbox
[144.201040268] DEBUG: Loading plugin minimize_size
[144.742965698] DEBUG: Loading plugin commands
[144.820928574] DEBUG: Loading plugin admin_user
[144.893884659] DEBUG: Loading plugin vagrant
[145.155906677] DEBUG: Loading plugin unattended_upgrades
[467.627048492] DEBUG: Tasklist:
    bootstrapvz.common.tasks.locale.LocaleBootstrapPackage
    bootstrapvz.common.tasks.packages.AddManifestPackages
    bootstrapvz.plugins.vagrant.tasks.CheckBoxPath
    bootstrapvz.common.tasks.filesystem.AddRequiredCommands
    bootstrapvz.common.tasks.ssh.AddOpenSSHPackage
    bootstrapvz.plugins.minimize_size.tasks.shrink.AddRequiredCommands
    bootstrapvz.common.tasks.apt.AddManifestSources
    bootstrapvz.common.tasks.apt.AddDefaultSources
    bootstrapvz.common.tasks.grub.AddGrubPackage
    bootstrapvz.common.tasks.bootstrap.AddRequiredCommands
    bootstrapvz.common.tasks.workspace.CreateWorkspace
    bootstrapvz.plugins.vagrant.tasks.CreateVagrantBoxDir
    bootstrapvz.common.tasks.loopback.AddRequiredCommands
    bootstrapvz.common.tasks.partitioning.AddRequiredCommands
    bootstrapvz.common.tasks.host.CheckExternalCommands
    bootstrapvz.plugins.unattended_upgrades.tasks.AddUnattendedUpgradesPackage
    bootstrapvz.plugins.vagrant.tasks.AddPackages
    bootstrapvz.plugins.admin_user.tasks.AddSudoPackage
    bootstrapvz.providers.virtualbox.tasks.packages.DefaultPackages
    bootstrapvz.common.tasks.loopback.Create
    bootstrapvz.common.tasks.volume.Attach
    bootstrapvz.common.tasks.partitioning.PartitionVolume
    bootstrapvz.common.tasks.partitioning.MapPartitions
    bootstrapvz.common.tasks.filesystem.Format
    bootstrapvz.common.tasks.filesystem.TuneVolumeFS
    bootstrapvz.common.tasks.filesystem.CreateMountDir
    bootstrapvz.common.tasks.filesystem.MountRoot
    bootstrapvz.common.tasks.bootstrap.Bootstrap
    bootstrapvz.plugins.minimize_size.tasks.mounts.AddFolderMounts
    bootstrapvz.common.tasks.filesystem.MountSpecials
    bootstrapvz.common.tasks.filesystem.CopyMountTable
    bootstrapvz.common.tasks.locale.GenerateLocale
    bootstrapvz.plugins.minimize_size.tasks.apt.FilterTranslationFiles
    bootstrapvz.common.tasks.apt.InstallTrustedKeys
    bootstrapvz.common.tasks.apt.WriteSources
    bootstrapvz.common.tasks.apt.AptUpdate
    bootstrapvz.common.tasks.apt.DisableDaemonAutostart
    bootstrapvz.common.tasks.apt.AptUpgrade
    bootstrapvz.common.tasks.packages.InstallPackages
    bootstrapvz.common.tasks.kernel.DetermineKernelVersion
    bootstrapvz.common.tasks.network.ConfigureNetworkIF
    bootstrapvz.common.tasks.security.EnableShadowConfig
    bootstrapvz.plugins.admin_user.tasks.PasswordlessSudo
    bootstrapvz.plugins.admin_user.tasks.CreateAdminUser
    bootstrapvz.common.tasks.filesystem.FStab
    bootstrapvz.common.tasks.grub.InstallGrub_2
    bootstrapvz.common.tasks.kernel.UpdateInitramfs
    bootstrapvz.common.tasks.grub.ConfigureGrub
    bootstrapvz.common.tasks.locale.SetLocalTimeCopy
    bootstrapvz.plugins.vagrant.tasks.PasswordlessSudo
    bootstrapvz.plugins.unattended_upgrades.tasks.EnablePeriodicUpgrades
    bootstrapvz.common.tasks.ssh.AddSSHKeyGeneration
    bootstrapvz.common.tasks.initd.InstallInitScripts
    bootstrapvz.plugins.admin_user.tasks.AdminUserPassword
    bootstrapvz.plugins.vagrant.tasks.CreateVagrantUser
    bootstrapvz.plugins.vagrant.tasks.AddInsecurePublicKey
    bootstrapvz.common.tasks.locale.SetTimezone
    bootstrapvz.plugins.vagrant.tasks.SetRootPassword
    bootstrapvz.common.tasks.network.SetHostname
    bootstrapvz.common.tasks.ssh.DisableSSHDNSLookup
    bootstrapvz.plugins.commands.tasks.ImageExecuteCommand
    bootstrapvz.common.tasks.apt.EnableDaemonAutostart
    bootstrapvz.common.tasks.cleanup.ClearMOTD
    bootstrapvz.plugins.minimize_size.tasks.mounts.RemoveFolderMounts
    bootstrapvz.common.tasks.apt.AptClean
    bootstrapvz.common.tasks.ssh.ShredHostkeys
    bootstrapvz.common.tasks.cleanup.CleanTMP
    bootstrapvz.common.tasks.apt.PurgeUnusedPackages
    bootstrapvz.common.tasks.network.RemoveDNSInfo
    bootstrapvz.common.tasks.filesystem.RemoveMountTable
    bootstrapvz.common.tasks.filesystem.UnmountRoot
    bootstrapvz.common.tasks.filesystem.DeleteMountDir
    bootstrapvz.plugins.minimize_size.tasks.shrink.Zerofree
    bootstrapvz.common.tasks.partitioning.UnmapPartitions
    bootstrapvz.common.tasks.volume.Detach
    bootstrapvz.plugins.vagrant.tasks.PackageBox
    bootstrapvz.plugins.vagrant.tasks.RemoveVagrantBoxDir
    bootstrapvz.common.tasks.volume.Delete
    bootstrapvz.common.tasks.workspace.DeleteWorkspace
[467.746973038] INFO: Adding locale package to bootstrap installation
[467.990875244] INFO: Adding packages from the manifest
[468.376874924] INFO: Checking if the vagrant box file already exists
[468.467950821] INFO: Adding commands required for formatting
[468.548059464] INFO: Adding openssh package
[468.628883362] INFO: Adding commands required for reducing volume size
[468.69802475] INFO: Adding sources from the manifest
[469.189882278] INFO: Adding default release sources
[469.310045242] INFO: Adding grub package
[469.387054443] INFO: Adding commands required for bootstrapping Debian
[469.456911087] INFO: Creating workspace
[471.091985703] INFO: Creating directory for the vagrant box
[471.162080765] INFO: Adding commands required for creating loopback volumes
[471.251964569] INFO: Adding commands required for partitioning the volume
[471.3139534] INFO: Checking availability of external commands
[473.268985748] DEBUG: Executing: type zerofree
[474.819898605] ERROR: can't start new thread
Traceback (most recent call last):
  File "/home/sramacher/teaching/ITS/vm-image/bootstrap-vz/bootstrapvz/base/main.py", line 122, in run
    tasklist.run(info=bootstrap_info, dry_run=dry_run)
  File "/home/sramacher/teaching/ITS/vm-image/bootstrap-vz/bootstrapvz/base/tasklist.py", line 43, in run
    task.run(info)
  File "/home/sramacher/teaching/ITS/vm-image/bootstrap-vz/bootstrapvz/common/tasks/host.py", line 18, in run
    log_check_call(['type ' + command], shell=True)
  File "/home/sramacher/teaching/ITS/vm-image/bootstrap-vz/bootstrapvz/common/tools.py", line 5, in log_check_call
    status, stdout, stderr = log_call(command, stdin, env, shell, cwd)
  File "/home/sramacher/teaching/ITS/vm-image/bootstrap-vz/bootstrapvz/common/tools.py", line 59, in log_call
    pool = ThreadPool(2)
  File "/usr/lib/python2.7/multiprocessing/dummy/__init__.py", line 151, in Pool
    return ThreadPool(processes, initializer, initargs)
  File "/usr/lib/python2.7/multiprocessing/pool.py", line 727, in __init__
    Pool.__init__(self, processes, initializer, initargs)
  File "/usr/lib/python2.7/multiprocessing/pool.py", line 159, in __init__
    self._repopulate_pool()
  File "/usr/lib/python2.7/multiprocessing/pool.py", line 223, in _repopulate_pool
    w.start()
  File "/usr/lib/python2.7/multiprocessing/dummy/__init__.py", line 75, in start
    threading.Thread.start(self)
  File "/usr/lib/python2.7/threading.py", line 745, in start
    _start_new_thread(self.__bootstrap, ())
error: can't start new thread
[475.727081299] ERROR: Rolling back
[740.953922272] DEBUG: Tasklist:
    bootstrapvz.plugins.vagrant.tasks.RemoveVagrantBoxDir
    bootstrapvz.common.tasks.workspace.DeleteWorkspace
[741.039037704] INFO: Removing the vagrant box directory
[741.2109375] INFO: Deleting workspace
[741.303920746] INFO: Successfully completed rollback

[nbraud]

@sebastinas That's interesting. I suspect it means the “fake” init in the PID namespace got killed.

[kevin-olbrich]

This is still an issue in master:

umount: /target/ebca06ce/root/proc: target is busy
(In some cases useful info about processes that
use the device is found by lsof(8) or fuser(1).)
Command 'umount /target/ebca06ce/root/proc' returned non-zero exit status 32

root@slde0005:~# ls -Al /etc/binfmt.d /run/binfmt.d /usr/lib/binfmt.d
ls: cannot access '/run/binfmt.d': No such file or directory
/etc/binfmt.d:
total 0

/usr/lib/binfmt.d:
total 0

root@slde0005:~# mount | grep target
/dev/mapper/nbd0p4 on /target/ebca06ce/root type ext4 (rw,relatime,data=ordered)
udev on /target/ebca06ce/root/dev type devtmpfs (rw,nosuid,relatime,size=4077768k,nr_inodes=1019442,mode=755)
none on /target/ebca06ce/root/proc type proc (rw,relatime)
none on /target/ebca06ce/root/sys type sysfs (rw,relatime)
binfmt_misc on /target/ebca06ce/root/proc/sys/fs/binfmt_misc type binfmt_misc (rw,nosuid,nodev,noexec,relatime)

[kevin-olbrich]

Problem fixed by removing these deps from my image profile:

- git
- curl
- libssl-dev
- zlib1g-dev
- libbz2-dev
- libreadline-dev
- libsqlite3-dev
- llvm
- libncurses5-dev
- libncursesw5-dev
- xz-utils
- tk-dev

Seems like one of these packages causes a chroot leak.