pvcreate fails to initialize a PV on top of a freshly-mapped LUKS device detecting an HFS+ file system signature

[Dmitrii Shcherbakov]

1) vaultlocker creates a new LUKS device and maps it via device mapper;
2) charm uses lvm to create a PV;
3) pvcreate fails as it detects something resembling a file system signature (which happens to be HFS+.

This just looks like a pure coincidence because it seems that untouched decrypted blocks of a fresh device mapper device have random garbage in them (which makes sense).

'['pvcreate', '/dev/mapper/crypt-419c1b6c-7efb-473d-a50f-4684ffeef0b4']'

hfsplus signature detected on /dev/mapper/crypt-419c1b6c-7efb-473d-a50f-4684ffeef0b4 at offset 1024. Wipe it? [y/n]: n

It's there but we obviously don't use HFS+ here:

blkid | grep crypt-419c1b6c-7efb-473d-a50f-4684ffeef0b4
/dev/mapper/crypt-419c1b6c-7efb-473d-a50f-4684ffeef0b4: UUID="4fb23380-ed34-3ea5-9565-2cdd5ea6cead" TYPE="hfsplus"

dd if=/dev/mapper/crypt-419c1b6c-7efb-473d-a50f-4684ffeef0b4 of=crypt-mapped-blocks.img bs=1M
^C175+0 records in
174+0 records out
182452224 bytes (182 MB, 174 MiB) copied, 0.942272 s, 194 MB/s

# 4858
xxd crypt-mapped-blocks.img | head -n 1000 | grep 0000400
00000400: 4858 97a3 178c 71a6 d69f efe6 af0a 5bbe HX....q.......[.

https://github.com/libyal/libfshfs/blob/master/documentation/Hierarchical%20File%20System%20(HFS).asciidoc#5-the-hfshfsx-volume

"\x48\x58" "HX" ⇒ HFSX

2018-07-24 22:34:50 DEBUG secrets-storage-relation-changed INFO:vaultlocker.dmcrypt:LUKS formatting /dev/nvme6n1p1 using UUID:419c1b6c-7efb-473d-a50f-4684ffeef0b4
2018-07-24 22:34:54 DEBUG secrets-storage-relation-changed INFO:vaultlocker.dmcrypt:udevadm trigger block/add
2018-07-24 22:34:54 DEBUG secrets-storage-relation-changed INFO:vaultlocker.dmcrypt:udevadm settle /dev/disk/by-uuid/419c1b6c-7efb-473d-a50f-4684ffeef0b4
2018-07-24 22:34:54 DEBUG secrets-storage-relation-changed DEBUG:urllib3.connectionpool:http://10.10.0.43:8200 "PUT /v1/charm-vaultlocker/fnos-nvme13/419c1b6c-7efb-473d-a50f-468
4ffeef0b4 HTTP/1.1" 204 0
2018-07-24 22:34:54 DEBUG secrets-storage-relation-changed DEBUG:urllib3.connectionpool:http://10.10.0.43:8200 "GET /v1/charm-vaultlocker/fnos-nvme13/419c1b6c-7efb-473d-a50f-468
4ffeef0b4 HTTP/1.1" 200 866
2018-07-24 22:34:54 DEBUG secrets-storage-relation-changed INFO:vaultlocker.dmcrypt:LUKS opening 419c1b6c-7efb-473d-a50f-4684ffeef0b4
2018-07-24 22:34:55 DEBUG secrets-storage-relation-changed INFO:root:Enabling systemd unit for [e-mail]
2018-07-24 22:34:55 DEBUG secrets-storage-relation-changed Created symlink from /etc/systemd/system/multi-user.target.wants/vaultlocker-decrypt@419c1b6c-7efb-473d-a50f-4684ffeef
0b4.service to /lib/systemd/system/vaultlocker-decrypt@.service.
2018-07-24 22:34:55 DEBUG secrets-storage-relation-changed Failed to find physical volume "/dev/mapper/crypt-419c1b6c-7efb-473d-a50f-4684ffeef0b4".
2018-07-24 22:34:56 DEBUG secrets-storage-relation-changed WARNING: hfsplus signature detected on /dev/mapper/crypt-419c1b6c-7efb-473d-a50f-4684ffeef0b4 at offset 1024. Wipe it? [y/n]: n
2018-07-24 22:34:56 DEBUG secrets-storage-relation-changed Aborted wiping of hfsplus.
2018-07-24 22:34:56 DEBUG secrets-storage-relation-changed 1 existing signature left on the device.
2018-07-24 22:34:56 DEBUG secrets-storage-relation-changed Aborting pvcreate on /dev/mapper/crypt-419c1b6c-7efb-473d-a50f-4684ffeef0b4.
2018-07-24 22:34:56 DEBUG secrets-storage-relation-changed Traceback (most recent call last):
2018-07-24 22:34:56 DEBUG secrets-storage-relation-changed File "/var/lib/juju/agents/unit-nvme-ceph-osd-3/charm/hooks/secrets-storage-relation-changed", line 657, in <module>
2018-07-24 22:34:56 DEBUG secrets-storage-relation-changed hooks.execute(sys.argv)
2018-07-24 22:34:56 DEBUG secrets-storage-relation-changed File "/var/lib/juju/agents/unit-nvme-ceph-osd-3/charm/hooks/charmhelpers/core/hookenv.py", line 823, in execute
2018-07-24 22:34:56 DEBUG secrets-storage-relation-changed self._hooks[hook_name]()
2018-07-24 22:34:56 DEBUG secrets-storage-relation-changed File "/var/lib/juju/agents/unit-nvme-ceph-osd-3/charm/hooks/secrets-storage-relation-changed", line 601, in secrets_storage_changed
2018-07-24 22:34:56 DEBUG secrets-storage-relation-changed prepare_disks_and_activate()
2018-07-24 22:34:56 DEBUG secrets-storage-relation-changed File "/var/lib/juju/agents/unit-nvme-ceph-osd-3/charm/hooks/secrets-storage-relation-changed", line 476, in prepare_disks_and_activate
2018-07-24 22:34:56 DEBUG secrets-storage-relation-changed config('osd-encrypt-keymanager'))
2018-07-24 22:34:56 DEBUG secrets-storage-relation-changed File "lib/ceph/utils.py", line 1412, in osdize
2018-07-24 22:34:56 DEBUG secrets-storage-relation-changed bluestore, key_manager)
2018-07-24 22:34:56 DEBUG secrets-storage-relation-changed File "lib/ceph/utils.py", line 1479, in osdize_dev
2018-07-24 22:34:56 DEBUG secrets-storage-relation-changed key_manager)
2018-07-24 22:34:56 DEBUG secrets-storage-relation-changed File "lib/ceph/utils.py", line 1612, in _ceph_volume
2018-07-24 22:34:56 DEBUG secrets-storage-relation-changed key_manager=key_manager))
2018-07-24 22:34:56 DEBUG secrets-storage-relation-changed File "lib/ceph/utils.py", line 1851, in _allocate_logical_volume
2018-07-24 22:34:56 DEBUG secrets-storage-relation-changed lvm.create_lvm_physical_volume(pv_dev)
2018-07-24 22:34:56 DEBUG secrets-storage-relation-changed File "/var/lib/juju/agents/unit-nvme-ceph-osd-3/charm/hooks/charmhelpers/contrib/storage/linux/lvm.py", line 92, in create_lvm_physical_volume
2018-07-24 22:34:56 DEBUG secrets-storage-relation-changed check_call(['pvcreate', block_device])
2018-07-24 22:34:56 DEBUG secrets-storage-relation-changed File "/usr/lib/python3.5/subprocess.py", line 581, in check_call
2018-07-24 22:34:56 DEBUG secrets-storage-relation-changed raise CalledProcessError(retcode, cmd)
2018-07-24 22:34:56 DEBUG secrets-storage-relation-changed subprocess.CalledProcessError: Command '['pvcreate', '/dev/mapper/crypt-419c1b6c-7efb-473d-a50f-4684ffeef0b4']' returned non-zero exit status 5

It seems like we need to force pvcreate to nuke anything it finds on those newly mapped devices as opposed to returning a non-zero exit code.

[Chris MacNaughton (chris.macnaughton)]

According to the man page for pvcreate, the partition table for a device should be erased before use, which can be done via:

dd if=/dev/zero of=PhysicalVolume bs=512 count=1

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/624418
Committed: https://git.openstack.org/cgit/openstack/charms.ceph/commit/?id=31ffa13124edce3490437b73fee5f0432c5eb7f8
Submitter: Zuul
Branch: master

commit 31ffa13124edce3490437b73fee5f0432c5eb7f8
Author: Chris MacNaughton <email address hidden>
Date: Tue Dec 11 15:59:23 2018 +0100

    Ensure that newly initialized disks are zero'd

    When creating a new encrypted disk, ensure that
    we zero the first region to ensure that pvcreate
    won't stumble on random artifacts

    Closes-Bug: #1783427
    Change-Id: Iac45e9c00d093befb893c61a3c3aee70ac4b851a

[Nikolay Vinogradov (nikolay.vinogradov)]

This is not fixed. I just stepped on a reproduction of this:
     2019-10-31 16:04:39 DEBUG secrets-storage-relation-changed partx: /dev/disk/by-dname/osddata5: failed to read partition table
     2019-10-31 16:04:39 DEBUG juju-log secrets-storage:253: get partitions: []
     2019-10-31 16:04:39 DEBUG secrets-storage-relation-changed Failed to find physical volume "/dev/bcache6".
     2019-10-31 16:04:39 WARNING juju-log secrets-storage:253: Support for use of upstream ``apt_pkg`` module in conjunctionwith charm-helpers is deprecated since 2019-06-25
     2019-10-31 16:04:40 DEBUG secrets-storage-relation-changed DEBUG:urllib3.connectionpool:Starting new HTTP connection (1): 172.20.10.53
     2019-10-31 16:04:40 DEBUG secrets-storage-relation-changed DEBUG:urllib3.connectionpool:http://172.20.10.53:8200 "POST /v1/auth/approle/login HTTP/1.1" 200 500
     2019-10-31 16:04:40 DEBUG secrets-storage-relation-changed INFO:vaultlocker.dmcrypt:LUKS formatting /dev/disk/by-dname/osddata5 using UUID:861482d7-f7a7-4d97-83ee-95e4b892ed86
     2019-10-31 16:04:43 DEBUG secrets-storage-relation-changed INFO:vaultlocker.dmcrypt:udevadm trigger block/add for /dev/disk/by-dname/osddata5
     2019-10-31 16:04:43 DEBUG secrets-storage-relation-changed INFO:vaultlocker.dmcrypt:udevadm settle /dev/disk/by-uuid/861482d7-f7a7-4d97-83ee-95e4b892ed86
     2019-10-31 16:04:43 DEBUG secrets-storage-relation-changed DEBUG:urllib3.connectionpool:http://172.20.10.53:8200 "PUT /v1/charm-vaultlocker/ucs-4b-block-2/861482d7-f7a7-4d97-83ee-95e4b892ed86 HTTP/1.1" 204 0
     2019-10-31 16:04:43 DEBUG secrets-storage-relation-changed DEBUG:urllib3.connectionpool:http://172.20.10.53:8200 "GET /v1/charm-vaultlocker/ucs-4b-block-2/861482d7-f7a7-4d97-83ee-95e4b892ed86 HTTP/1.1" 200 866
     2019-10-31 16:04:43 DEBUG secrets-storage-relation-changed INFO:vaultlocker.dmcrypt:LUKS opening 861482d7-f7a7-4d97-83ee-95e4b892ed86
     2019-10-31 16:04:45 DEBUG secrets-storage-relation-changed INFO:root:Enabling systemd unit for [e-mail]
     2019-10-31 16:04:45 DEBUG secrets-storage-relation-changed Created symlink /etc/systemd/system/multi-user.target.wants/[e-mail] → /lib/systemd/system/vaultlocker-decrypt@.service.
     2019-10-31 16:04:45 DEBUG secrets-storage-relation-changed 1+0 records in
     2019-10-31 16:04:45 DEBUG secrets-storage-relation-changed 1+0 records out
     2019-10-31 16:04:45 DEBUG secrets-storage-relation-changed 512 bytes copied, 0.000446392 s, 1.1 MB/s
     2019-10-31 16:04:46 DEBUG secrets-storage-relation-changed Failed to find physical volume "/dev/mapper/crypt-861482d7-f7a7-4d97-83ee-95e4b892ed86".
     2019-10-31 16:04:45 DEBUG secrets-storage-relation-changed INFO:root:Enabling systemd unit for [e-mail]
     2019-10-31 16:04:45 DEBUG secrets-storage-relation-changed Created symlink /etc/systemd/system/multi-user.target.wants/[e-mail] → /lib/systemd/system/vaultlocker-decrypt@.service.
     2019-10-31 16:04:45 DEBUG secrets-storage-rel...

[Nikolay Vinogradov (nikolay.vinogradov)]

See also: LP:1851049