[2.1.5] Deployment failure on reprovisioned systems with bcache devices

[James Page]

We're currently unable to deploy Xenial machines using PCI NVMe bcache devices; install fails with the following error:

Apr 6 10:55:26 mutus cloud-init[3633]: Creating new GPT entries.
Apr 6 10:55:26 mutus kernel: [ 51.753265] sda:
Apr 6 10:55:26 mutus cloud-init[3633]: The operation has completed successfully.
Apr 6 10:55:26 mutus kernel: [ 51.771281] sda:
Apr 6 10:55:26 mutus kernel: [ 51.790637] sda:
Apr 6 10:55:27 mutus kernel: [ 52.237888] nvme0n1:
Apr 6 10:55:28 mutus cloud-init[3633]: Creating new GPT entries.
Apr 6 10:55:28 mutus kernel: [ 53.259122] nvme0n1:
Apr 6 10:55:28 mutus cloud-init[3633]: The operation has completed successfully.
Apr 6 10:55:28 mutus kernel: [ 53.307976] nvme0n1:
Apr 6 10:55:28 mutus kernel: [ 53.324729] nvme0n1:
Apr 6 10:55:28 mutus kernel: [ 53.356890] nvme0n1:
Apr 6 10:55:28 mutus kernel: [ 53.529895] sda:
Apr 6 10:55:28 mutus kernel: [ 53.531137] sda:
Apr 6 10:55:28 mutus kernel: [ 53.557188] sda:
Apr 6 10:55:28 mutus kernel: [ 53.574467] sda:
Apr 6 10:55:29 mutus kernel: [ 54.578195] sda: sda1
Apr 6 10:55:29 mutus kernel: [ 54.688927] sda: sda1
Apr 6 10:55:29 mutus kernel: [ 54.788675] sda: sda1
Apr 6 10:55:29 mutus kernel: [ 54.889419] sda: sda1
Apr 6 10:55:30 mutus kernel: [ 54.971285] sda: sda1
Apr 6 10:55:30 mutus kernel: [ 55.065077] sda: sda1
Apr 6 10:55:30 mutus kernel: [ 55.149155] sda: sda1
Apr 6 10:55:30 mutus kernel: [ 55.354850] sda: sda1
Apr 6 10:55:30 mutus kernel: [ 55.405415] sda: sda1
Apr 6 10:55:30 mutus kernel: [ 55.407443] sda: sda1 sda2
Apr 6 10:55:31 mutus kernel: [ 56.408871] sda: sda1 sda2
Apr 6 10:55:31 mutus kernel: [ 56.478676] sda: sda1 sda2
Apr 6 10:55:31 mutus kernel: [ 56.573829] sda: sda1 sda2
Apr 6 10:55:31 mutus kernel: [ 56.671560] sda: sda1 sda2
Apr 6 10:55:31 mutus kernel: [ 56.767427] sda: sda1 sda2
Apr 6 10:55:31 mutus kernel: [ 56.875916] sda: sda1 sda2
Apr 6 10:55:32 mutus kernel: [ 56.962714] sda: sda1 sda2
Apr 6 10:55:32 mutus kernel: [ 57.172994] sda: sda1 sda2
Apr 6 10:55:32 mutus kernel: [ 57.223798] sda: sda1 sda2
Apr 6 10:55:32 mutus kernel: [ 57.226333] sda: sda1 sda2 sda3
Apr 6 10:55:33 mutus kernel: [ 58.227166] sda: sda1 sda2 sda3
Apr 6 10:55:33 mutus kernel: [ 58.303846] sda: sda1 sda2 sda3
Apr 6 10:55:33 mutus kernel: [ 58.415606] sda: sda1 sda2 sda3
Apr 6 10:55:33 mutus kernel: [ 58.515676] sda: sda1 sda2 sda3
Apr 6 10:55:33 mutus kernel: [ 58.615585] sda: sda1 sda2 sda3
Apr 6 10:55:33 mutus kernel: [ 58.734039] sda: sda1 sda2 sda3
Apr 6 10:55:33 mutus kernel: [ 58.833126] sda: sda1 sda2 sda3
Apr 6 10:55:34 mutus kernel: [ 59.069875] nvme0n1:
Apr 6 10:55:34 mutus kernel: [ 59.100977] nvme0n1:
Apr 6 10:55:34 mutus kernel: [ 59.134993] nvme0n1:
Apr 6 10:55:34 mutus kernel: [ 59.174833] nvme0n1:
Apr 6 10:55:34 mutus kernel: [ 59.190097] nvme0n1: p1
Apr 6 10:55:34 mutus kernel: [ 59.794421] bcache: bch_journal_replay() journal replay done, 105 keys in 27 entries, seq 20051589
Apr 6 10:55:34 mutus kernel: [ 59.794620] bcache: register_cache() registered cache device nvme0n1p1
Apr 6 10:55:35 mutus kernel: [ 60.190482] bcache: register_bcache() error opening /dev/nvme0n1p1: device already registered
Apr 6 10:55:35 mutus kernel: [ 60.204020] bcache: register_bcache() error opening /dev/nvme0n1p1: device already registered
Apr 6 10:55:35 mutus kernel: [ 60.208338] bcache: register_bcache() error opening /dev/nvme0n1p1: device already registered
Apr 6 10:55:35 mutus kernel: [ 60.212611] bcache: register_bcache() error opening /dev/nvme0n1p1: device already registered
Apr 6 10:55:35 mutus kernel: [ 60.223886] bcache: register_bcache() error opening /dev/nvme0n1p1: device already registered
Apr 6 10:55:35 mutus kernel: [ 60.237373] bcache: register_bcache() error opening /dev/nvme0n1p1: device already registered
Apr 6 10:55:35 mutus kernel: [ 60.249949] bcache: register_bcache() error opening /dev/nvme0n1p1: device already registered
Apr 6 10:55:35 mutus kernel: [ 60.254018] bcache: register_bcache() error opening /dev/nvme0n1p1: device already registered
Apr 6 10:55:35 mutus kernel: [ 60.258041] bcache: register_bcache() error opening /dev/nvme0n1p1: device already registered
Apr 6 10:55:35 mutus kernel: [ 60.268776] bcache: register_bcache() error opening /dev/nvme0n1p1: device already registered
Apr 6 10:55:35 mutus kernel: [ 60.282611] bcache: register_bcache() error opening /dev/nvme0n1p1: device already registered
Apr 6 10:55:35 mutus kernel: [ 60.295236] bcache: register_bcache() error opening /dev/nvme0n1p1: device already registered
Apr 6 10:55:35 mutus kernel: [ 60.299748] bcache: register_bcache() error opening /dev/nvme0n1p1: device already registered
Apr 6 10:55:35 mutus kernel: [ 60.303715] bcache: register_bcache() error opening /dev/nvme0n1p1: device already registered
Apr 6 10:55:35 mutus kernel: [ 60.315059] bcache: register_bcache() error opening /dev/nvme0n1p1: device already registered
Apr 6 10:55:35 mutus kernel: [ 60.329561] bcache: register_bcache() error opening /dev/nvme0n1p1: device already registered
Apr 6 10:55:35 mutus kernel: [ 60.343202] bcache: register_bcache() error opening /dev/nvme0n1p1: device already registered
Apr 6 10:55:35 mutus kernel: [ 60.347250] bcache: register_bcache() error opening /dev/nvme0n1p1: device already registered
Apr 6 10:55:35 mutus kernel: [ 60.351080] bcache: register_bcache() error opening /dev/nvme0n1p1: device already registered
Apr 6 10:55:35 mutus kernel: [ 60.361475] bcache: register_bcache() error opening /dev/nvme0n1p1: device already registered
Apr 6 10:55:35 mutus cloud-init[3633]: Failed to exclusively open path: /dev/nvme0n1p1
Apr 6 10:55:35 mutus cloud-init[3633]: Traceback (most recent call last):
Apr 6 10:55:35 mutus cloud-init[3633]: File "/curtin/curtin/block/__init__.py", line 773, in exclusive_open
Apr 6 10:55:35 mutus cloud-init[3633]: fd = os.open(path, os.O_RDWR | os.O_EXCL)
Apr 6 10:55:35 mutus cloud-init[3633]: OSError: [Errno 16] Device or resource busy: '/dev/nvme0n1p1'
Apr 6 10:55:35 mutus cloud-init[3633]: Device holders with exclusive access: []
Apr 6 10:55:35 mutus cloud-init[3633]: Device mounts: []
Apr 6 10:55:35 mutus cloud-init[3633]: An error occured handling 'nvme0n1-part1': OSError - [Errno 16] Device or resource busy: '/dev/nvme0n1p1'
Apr 6 10:55:35 mutus cloud-init[3633]: [Errno 16] Device or resource busy: '/dev/nvme0n1p1'
Apr 6 10:55:35 mutus cloud-init[3633]: curtin: Installation failed with exception: Unexpected error while running command.
Apr 6 10:55:35 mutus cloud-init[3633]: Command: ['curtin', 'block-meta', 'custom']
Apr 6 10:55:35 mutus cloud-init[3633]: Exit code: 3
Apr 6 10:55:35 mutus cloud-init[3633]: Reason: -
Apr 6 10:55:35 mutus cloud-init[3633]: Stdout: Creating new GPT entries.
Apr 6 10:55:35 mutus cloud-init[3633]: The operation has completed successfully.
Apr 6 10:55:35 mutus cloud-init[3633]: Creating new GPT entries.
Apr 6 10:55:35 mutus cloud-init[3633]: The operation has completed successfully.
Apr 6 10:55:35 mutus cloud-init[3633]: Failed to exclusively open path: /dev/nvme0n1p1
Apr 6 10:55:35 mutus cloud-init[3633]: Traceback (most recent call last):
Apr 6 10:55:35 mutus cloud-init[3633]: File "/curtin/curtin/block/__init__.py", line 773, in exclusive_open
Apr 6 10:55:35 mutus cloud-init[3633]: fd = os.open(path, os.O_RDWR | os.O_EXCL)
Apr 6 10:55:35 mutus cloud-init[3633]: OSError: [Errno 16] Device or resource busy: '/dev/nvme0n1p1'
Apr 6 10:55:35 mutus cloud-init[3633]: Device holders with exclusive access: []
Apr 6 10:55:35 mutus cloud-init[3633]: Device mounts: []
Apr 6 10:55:35 mutus cloud-init[3633]: An error occured handling 'nvme0n1-part1': OSError - [Errno 16] Device or resource busy: '/dev/nvme0n1p1'
Apr 6 10:55:35 mutus cloud-init[3633]: [Errno 16] Device or resource busy: '/dev/nvme0n1p1'
Apr 6 10:55:36 mutus cloud-init[3633]:
Apr 6 10:55:36 mutus cloud-init[3633]: Stderr: ''
Apr 6 10:55:36 mutus cloud-init[3633]: Unexpected error while running command.
Apr 6 10:55:36 mutus cloud-init[3633]: Command: ['curtin', 'block-meta', 'custom']
Apr 6 10:55:36 mutus cloud-init[3633]: Exit code: 3
Apr 6 10:55:36 mutus cloud-init[3633]: Reason: -
Apr 6 10:55:36 mutus cloud-init[3633]: Stdout: Creating new GPT entries.
Apr 6 10:55:36 mutus cloud-init[3633]: The operation has completed successfully.
Apr 6 10:55:36 mutus cloud-init[3633]: Creating new GPT entries.
Apr 6 10:55:36 mutus cloud-init[3633]: The operation has completed successfully.
Apr 6 10:55:36 mutus cloud-init[3633]: Failed to exclusively open path: /dev/nvme0n1p1
Apr 6 10:55:36 mutus cloud-init[3633]: Traceback (most recent call last):
Apr 6 10:55:36 mutus cloud-init[3633]: File "/curtin/curtin/block/__init__.py", line 773, in exclusive_open
Apr 6 10:55:36 mutus cloud-init[3633]: fd = os.open(path, os.O_RDWR | os.O_EXCL)
Apr 6 10:55:36 mutus cloud-init[3633]: OSError: [Errno 16] Device or resource busy: '/dev/nvme0n1p1'
Apr 6 10:55:36 mutus cloud-init[3633]: Device holders with exclusive access: []
Apr 6 10:55:36 mutus cloud-init[3633]: Device mounts: []
Apr 6 10:55:36 mutus cloud-init[3633]: An error occured handling 'nvme0n1-part1': OSError - [Errno 16] Device or resource busy: '/dev/nvme0n1p1'
Apr 6 10:55:37 mutus cloud-init[3633]: [Errno 16] Device or resource busy: '/dev/nvme0n1p1'
Apr 6 10:55:37 mutus cloud-init[3633]:
Apr 6 10:55:37 mutus cloud-init[3633]: Stderr: ''
Apr 6 10:55:37 mutus cloud-init[3633]: Cloud-init v. 0.7.9 running 'modules:final' at Thu, 06 Apr 2017 10:55:21 +0000. Up 45.64 seconds.
Apr 6 10:55:37 mutus cloud-init[3633]: 2017-04-06 10:55:35,776 - util.py[WARNING]: Failed running /var/lib/cloud/instance/scripts/part-001 [3]
Apr 6 10:55:37 mutus cloud-init[3633]: 2017-04-06 10:55:35,779 - cc_scripts_user.py[WARNING]: Failed to run module scripts-user (scripts in /var/lib/cloud/instance/scripts)
Apr 6 10:55:37 mutus cloud-init[3633]: 2017-04-06 10:55:35,830 - util.py[WARNING]: Running module scripts-user (<module 'cloudinit.config.cc_scripts_user' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_scripts_user.py'>) failed

The servers are configured with a single cache-set and two bcache devices; one fronting sda (created using the bcache storage profile in MAAS) and the second fronting a larger 3TB spindle.

We also tried with just a single bcache, but saw the same issue.

[Ryan Beisner (1chb1n)]

It is worth noting that this same hardware deployed successfully with bcache with MAAS 1.9 yesterday.

[Andres Rodriguez (andreserl)]

This may be related to:

But in the meantime, can you attach:

 * Curtin version on MAAS Server (dpkg -l | grep curtin)
 * Install log from UI or CLI (maas <user> node-results read system_id=<your_system> result_type=1 | grep "\"data\"" | cut -d"\"" -f4 | base64 --decode)
 * Curtin config: maas <user> machine get-curtin-config <system_id_of_machine>
 * cloud-init logs from the deployment ephemeral enviroment (//var/log/cloud-init*)

[James Page (james-page)]

Note that machines had previously been deployed with MAAS 1.9 using bcache; working on a theory that the quick erase function in MAAS is not effective against bcache cache devices.

I was able to recover a cache device by creating the partition table on the disk, and the kernel detected it and grabbed it for bcache.

Stopping the cache device and using wipefs on the partition appears to have worked - just testing now.

[James Page (james-page)]

FTR

echo 1 > /sys/fs/bcache/bab46690-0a04-418b-8c1b-41df57821259/stop
wipefs -a /dev/nvme0n1p1

[James Page (james-page)]

OK so that appears to have done the trick; we:

1) deployed the machine using flat layout on /dev/sda only
2) added the partition to /dev/nvme0n1 - which triggered the udev rule for bcache to consume the device.
3) at this point in time it was not possible to wipefs the partition as it was busy
4) stopped the bcache cache device using echo 1 > /sys/fs/bcache/bab46690-0a04-418b-8c1b-41df57821259/stop
5) wipefs -a /dev/nvme0n1p1

Released, reconfigured and re-deployed the machine using bcache layout with multi bcache devices and the machine now fully deploys with the required configuration.

[James Page (james-page)]

Layout on finally deployed system:

$ df -h
Filesystem Size Used Avail Use% Mounted on
udev 126G 0 126G 0% /dev
tmpfs 26G 9.6M 26G 1% /run
/dev/bcache0 274G 9.4G 251G 4% /
tmpfs 126G 0 126G 0% /dev/shm
tmpfs 5.0M 0 5.0M 0% /run/lock
tmpfs 126G 0 126G 0% /sys/fs/cgroup
/dev/bcache1 2.8T 33M 2.8T 1% /srv
/dev/sda2 976M 57M 853M 7% /boot
/dev/sda1 511M 3.4M 508M 1% /boot/efi
tmpfs 26G 0 26G 0% /run/user/1000

[Andres Rodriguez (andreserl)]

Marked this invalid for MAAS provided that this is related to the wiping of disks when putting a new layout.

[Ryan Harper (raharper)]

Can you provide the curtin config sent to the machine?

[James Page (james-page)]

ii curtin-common 0.1.0~bzr470-0ubuntu1~16.04.1 all Library and tools for curtin installer
ii python-curtin 0.1.0~bzr470-0ubuntu1~16.04.1 all Library and tools for curtin installer
ii python3-curtin 0.1.0~bzr470-0ubuntu1~16.04.1 all Library and tools for curtin installer

[James Page (james-page)]

Messages from quick erase on release:

Apr 6 10:20:38 clerke cloud-init[3866]: nvme0n1, sda, sdb to be wiped.
Apr 6 10:20:38 clerke kernel: [ 52.353800] bcache: register_bcache() error opening /dev/nvme0n1p1: device already registered
Apr 6 10:20:38 clerke cloud-init[3866]: nvme0n1: starting quick wipe.
Apr 6 10:20:38 clerke kernel: [ 52.370741] bcache: register_bcache() error opening /dev/sda3: device already registered
Apr 6 10:20:38 clerke cloud-init[3866]: nvme0n1: successfully quickly wiped.
Apr 6 10:20:38 clerke cloud-init[3866]: sda: starting quick wipe.
Apr 6 10:20:38 clerke cloud-init[3866]: sda: successfully quickly wiped.
Apr 6 10:20:38 clerke cloud-init[3866]: sdb: starting quick wipe.
Apr 6 10:20:38 clerke cloud-init[3866]: sdb: successfully quickly wiped.
Apr 6 10:20:38 clerke cloud-init[3866]: All disks have been successfully wiped.
Apr 6 10:20:38 clerke ntpd[3788]: Soliciting pool server 91.189.91.157
Apr 6 10:20:38 clerke cloud-init[3866]: Success

[Ryan Harper (raharper)]

Do you have the entire log? Curtin starts the wiping process at the very beginning and that output is highly useful in understanding what cleanup of device holders happened.

[Ryan Harper (raharper)]

OK, I've recreated the issue;

When curtin first starts; it examines the system to determine which block devices are already in-use and generates a recursive strategy to wipe them clean taking into account layered block devices.

In this system's case there is a single bcache cache device and two backing devices. Curtin first will stop the bcache cache set device via writing to sysfs; THis triggers in-kernel bcache teardown.

However, curtin did not *wait* for bcache devices to become de-registered and instead proceeded on attempting to wipe the backing devices. Since these devices were still registered to various bcache devices our exclusive open of the block dev failed and we could not wipe the device.

The fix here in curtin is to include a reasonable timeout while watching for the kernel to remove the expected bcache block devices; and then proceed with the remaining operations required to wipe the device.

[Scott Moser (smoser)]

This bug is believed to be fixed in curtin in 17.1. If this is still a problem for you, please make a comment and set the state back to New

Thank you.