I just upgraded my cluster to Proxmox 5.1 and am trying to upgrade one of the Ceph OSDs to Bluestore. I've shut down and removed the old OSD completely. From the crush map, auth, and the cluster:
For completeness, I've destroyed the zvol as well. I'll now try to create the OSD from scratch:
However, in the log, I see the following:
I noticed there are several issues with incorrect permissions on block devices with older versions of Ceph so I checked:
However, /var/lib/ceph/tmp is mysteriously owned by root. Perhaps it's related to issue 21068 on the Ceph bugtracker. I don't know enough about the internals of Ceph to be able to really tell and I don't see a reference to the block symlink although it's clearly trying to create one.
Versions:
Code:
cluster:
id: 2b70b442-d912-4d6b-b9ad-b359b9339e4f
health: HEALTH_WARN
Degraded data redundancy: 25803/77394 objects degraded (33.340%), 128 pgs unclean, 128 pgs degraded, 128 pgs undersized
services:
mon: 3 daemons, quorum 0,1,2
mgr: triglav(active), standbys: svantevit, perun
osd: 2 osds: 2 up, 2 in
data:
pools: 1 pools, 128 pgs
objects: 25798 objects, 91585 MB
usage: 197 GB used, 723 GB / 921 GB avail
pgs: 25803/77394 objects degraded (33.340%)
128 active+undersized+degraded
io:
client: 422 kB/s wr, 0 op/s rd, 24 op/s wr
For completeness, I've destroyed the zvol as well. I'll now try to create the OSD from scratch:
Code:
root@perun:/var/lib/ceph# zfs create -V 512G Data/Virtualization/Ceph
root@perun:/var/lib/ceph# ls -l /dev/zvol/Data/Virtualization/Ceph
lrwxrwxrwx 1 root root 13 Oct 31 01:10 /dev/zvol/Data/Virtualization/Ceph -> ../../../zd16
root@perun:/var/lib/ceph# ceph-disk prepare --bluestore /dev/zd16
Creating new GPT entries.
Setting name!
partNum is 0
REALLY setting name!
The operation has completed successfully.
Setting name!
partNum is 1
REALLY setting name!
The operation has completed successfully.
The operation has completed successfully.
specified blocksize 4096 is less than device physical sector size 8192
switching to logical sector size 512
meta-data=/dev/zd16p1 isize=2048 agcount=4, agsize=6400 blks
= sectsz=512 attr=2, projid32bit=1
= crc=1 finobt=1, sparse=0, rmapbt=0, reflink=0
data = bsize=4096 blocks=25600, imaxpct=25
= sunit=0 swidth=0 blks
naming =version 2 bsize=4096 ascii-ci=0 ftype=1
log =internal log bsize=4096 blocks=864, version=2
= sectsz=512 sunit=0 blks, lazy-count=1
realtime =none extsz=4096 blocks=0, rtextents=0
The operation has completed successfully.
However, in the log, I see the following:
Code:
Oct 31 01:13:02 perun.gaea.mythicnet.org kernel: zd16: p1 [131/1742]
Oct 31 01:13:20 perun.gaea.mythicnet.org kernel: zd16: p1 p2
Oct 31 01:13:20 perun.gaea.mythicnet.org systemd[1]: Starting Ceph disk activation: /dev/zd16p2...
Oct 31 01:13:21 perun.gaea.mythicnet.org sh[19055]: main_trigger: main_trigger: Namespace(cluster='ceph', dev='/dev/zd16p2', dmcrypt=None, dmcrypt_key_dir='/etc/ceph/dmcrypt-keys', func=<function main_trigger at 0x7fa4ee6b0de8>, log_stdout=True, prepend_to_path='/usr/bin', prog='ceph-disk', setgroup=None, setuser=N
one, statedir='/var/lib/ceph', sync=True, sysconfdir='/etc/ceph', verbose=True)
Oct 31 01:13:21 perun.gaea.mythicnet.org sh[19055]: command: Running command: /sbin/init --version
Oct 31 01:13:21 perun.gaea.mythicnet.org sh[19055]: command_check_call: Running command: /bin/chown ceph:ceph /dev/zd16p2
Oct 31 01:13:21 perun.gaea.mythicnet.org sh[19055]: command: Running command: /sbin/blkid -o udev -p /dev/zd16p2
Oct 31 01:13:23 perun.gaea.mythicnet.org sh[19055]: command: Running command: /sbin/blkid -o udev -p /dev/zd16p2
Oct 31 01:13:23 perun.gaea.mythicnet.org sh[19055]: main_trigger: trigger /dev/zd16p2 parttype cafecafe-9b03-4f30-b4c6-b4b80ceff106 uuid 1fc45fb4-2272-44cd-9417-4c5f40f9c72e
Oct 31 01:13:23 perun.gaea.mythicnet.org sh[19055]: command: Running command: /usr/sbin/ceph-disk --verbose activate-block /dev/zd16p2
Oct 31 01:13:23 perun.gaea.mythicnet.org sh[19055]: main_trigger:
Oct 31 01:13:23 perun.gaea.mythicnet.org sh[19055]: main_trigger: get_dm_uuid: get_dm_uuid /dev/zd16p2 uuid path is /sys/dev/block/230:18/dm/uuid
Oct 31 01:13:23 perun.gaea.mythicnet.org sh[19055]: command: Running command: /sbin/blkid -o udev -p /dev/zd16p2
Oct 31 01:13:23 perun.gaea.mythicnet.org sh[19055]: command: Running command: /usr/bin/ceph-osd --get-device-fsid /dev/zd16p2
Oct 31 01:13:23 perun.gaea.mythicnet.org sh[19055]: get_space_osd_uuid: Block /dev/zd16p2 has OSD UUID 00000000-0000-0000-0000-000000000000
Oct 31 01:13:23 perun.gaea.mythicnet.org sh[19055]: main_activate_space: activate: OSD device not present, not starting, yet
Oct 31 01:13:23 perun.gaea.mythicnet.org systemd[1]: Started Ceph disk activation: /dev/zd16p2.
Oct 31 01:13:37 perun.gaea.mythicnet.org kernel: zd16: p1 p2
Oct 31 01:13:37 perun.gaea.mythicnet.org systemd[1]: Starting Ceph disk activation: /dev/zd16p2...
Oct 31 01:13:38 perun.gaea.mythicnet.org sh[21928]: main_trigger: main_trigger: Namespace(cluster='ceph', dev='/dev/zd16p2', dmcrypt=None, dmcrypt_key_dir='/etc/ceph/dmcrypt-keys', func=<function main_trigger at 0x7f1a30c5dde8>, log_stdout=True, prepend_to_path='/usr/bin', prog='ceph-disk', setgroup=None, setuser=N
one, statedir='/var/lib/ceph', sync=True, sysconfdir='/etc/ceph', verbose=True)
Oct 31 01:13:38 perun.gaea.mythicnet.org sh[21928]: command: Running command: /sbin/init --version
Oct 31 01:13:38 perun.gaea.mythicnet.org sh[21928]: command_check_call: Running command: /bin/chown ceph:ceph /dev/zd16p2
Oct 31 01:13:38 perun.gaea.mythicnet.org sh[21928]: command: Running command: /sbin/blkid -o udev -p /dev/zd16p2
Oct 31 01:13:38 perun.gaea.mythicnet.org sh[21928]: command: Running command: /sbin/blkid -o udev -p /dev/zd16p2
Oct 31 01:13:38 perun.gaea.mythicnet.org sh[21928]: main_trigger: trigger /dev/zd16p2 parttype cafecafe-9b03-4f30-b4c6-b4b80ceff106 uuid 1fc45fb4-2272-44cd-9417-4c5f40f9c72e
Oct 31 01:13:38 perun.gaea.mythicnet.org sh[21928]: command: Running command: /usr/sbin/ceph-disk --verbose activate-block /dev/zd16p2
Oct 31 01:13:38 perun.gaea.mythicnet.org sh[21928]: main_trigger:
Oct 31 01:13:38 perun.gaea.mythicnet.org sh[21928]: main_trigger: get_dm_uuid: get_dm_uuid /dev/zd16p2 uuid path is /sys/dev/block/230:18/dm/uuid
Oct 31 01:13:38 perun.gaea.mythicnet.org sh[21928]: command: Running command: /sbin/blkid -o udev -p /dev/zd16p2
Oct 31 01:13:38 perun.gaea.mythicnet.org sh[21928]: command: Running command: /usr/bin/ceph-osd --get-device-fsid /dev/zd16p2
Oct 31 01:13:38 perun.gaea.mythicnet.org sh[21928]: get_space_osd_uuid: Block /dev/zd16p2 has OSD UUID 00000000-0000-0000-0000-000000000000
Oct 31 01:13:38 perun.gaea.mythicnet.org sh[21928]: main_activate_space: activate: OSD device not present, not starting, yet
Oct 31 01:13:38 perun.gaea.mythicnet.org systemd[1]: Started Ceph disk activation: /dev/zd16p2.
Oct 31 01:13:43 perun.gaea.mythicnet.org kernel: XFS (zd16p1): Mounting V5 Filesystem
Oct 31 01:13:43 perun.gaea.mythicnet.org kernel: XFS (zd16p1): Ending clean mount
Oct 31 01:13:43 perun.gaea.mythicnet.org kernel: XFS (zd16p1): Unmounting Filesystem
Oct 31 01:14:00 perun.gaea.mythicnet.org systemd[1]: Starting Proxmox VE replication runner...
Oct 31 01:14:01 perun.gaea.mythicnet.org systemd[1]: Started Proxmox VE replication runner.
Oct 31 01:14:04 perun.gaea.mythicnet.org kernel: zd16: p1 p2
Oct 31 01:14:04 perun.gaea.mythicnet.org systemd[1]: Starting Ceph disk activation: /dev/zd16p2...
Oct 31 01:14:04 perun.gaea.mythicnet.org systemd[1]: Starting Ceph disk activation: /dev/zd16p1...
Oct 31 01:14:04 perun.gaea.mythicnet.org sh[27999]: main_trigger: main_trigger: Namespace(cluster='ceph', dev='/dev/zd16p2', dmcrypt=None, dmcrypt_key_dir='/etc/ceph/dmcrypt-keys', func=<function main_trigger at 0x7f063e9f1de8>, log_stdout=True, prepend_to_path='/usr/bin', prog='ceph-disk', setgroup=None, setuser=N
one, statedir='/var/lib/ceph', sync=True, sysconfdir='/etc/ceph', verbose=True)
Oct 31 01:14:04 perun.gaea.mythicnet.org sh[27999]: command: Running command: /sbin/init --version
Oct 31 01:14:04 perun.gaea.mythicnet.org sh[27999]: command_check_call: Running command: /bin/chown ceph:ceph /dev/zd16p2
Oct 31 01:14:04 perun.gaea.mythicnet.org sh[27999]: command: Running command: /sbin/blkid -o udev -p /dev/zd16p2
Oct 31 01:14:04 perun.gaea.mythicnet.org sh[27999]: command: Running command: /sbin/blkid -o udev -p /dev/zd16p2
Oct 31 01:14:04 perun.gaea.mythicnet.org sh[27999]: main_trigger: trigger /dev/zd16p2 parttype cafecafe-9b03-4f30-b4c6-b4b80ceff106 uuid 1fc45fb4-2272-44cd-9417-4c5f40f9c72e
Oct 31 01:14:04 perun.gaea.mythicnet.org sh[27999]: command: Running command: /usr/sbin/ceph-disk --verbose activate-block /dev/zd16p2
Oct 31 01:14:04 perun.gaea.mythicnet.org sh[28008]: main_trigger: main_trigger: Namespace(cluster='ceph', dev='/dev/zd16p1', dmcrypt=None, dmcrypt_key_dir='/etc/ceph/dmcrypt-keys', func=<function main_trigger at 0x7fefb9954de8>, log_stdout=True, prepend_to_path='/usr/bin', prog='ceph-disk', setgroup=None, setuser=N
one, statedir='/var/lib/ceph', sync=True, sysconfdir='/etc/ceph', verbose=True)
Oct 31 01:14:04 perun.gaea.mythicnet.org sh[28008]: command: Running command: /sbin/init --version
Oct 31 01:14:04 perun.gaea.mythicnet.org sh[28008]: command_check_call: Running command: /bin/chown ceph:ceph /dev/zd16p1
Oct 31 01:14:04 perun.gaea.mythicnet.org sh[28008]: command: Running command: /sbin/blkid -o udev -p /dev/zd16p1
Oct 31 01:14:04 perun.gaea.mythicnet.org sh[28008]: command: Running command: /sbin/blkid -o udev -p /dev/zd16p1
Oct 31 01:14:04 perun.gaea.mythicnet.org sh[28008]: main_trigger: trigger /dev/zd16p1 parttype 4fbd7e29-9d25-41b8-afd0-062c0ceff05d uuid f9242a92-09b1-458a-8dd9-124f3ce3e772
Oct 31 01:14:04 perun.gaea.mythicnet.org sh[28008]: command: Running command: /usr/sbin/ceph-disk --verbose activate /dev/zd16p1
Oct 31 01:14:05 perun.gaea.mythicnet.org systemd[1]: Stopped Ceph disk activation: /dev/zd16p1.
Oct 31 01:14:05 perun.gaea.mythicnet.org systemd[1]: Starting Ceph disk activation: /dev/zd16p1...
Oct 31 01:14:05 perun.gaea.mythicnet.org sh[27999]: main_trigger:
Oct 31 01:14:05 perun.gaea.mythicnet.org sh[27999]: main_trigger: get_dm_uuid: get_dm_uuid /dev/zd16p2 uuid path is /sys/dev/block/230:18/dm/uuid
Oct 31 01:14:05 perun.gaea.mythicnet.org sh[27999]: command: Running command: /sbin/blkid -o udev -p /dev/zd16p2
Oct 31 01:14:05 perun.gaea.mythicnet.org sh[27999]: command: Running command: /usr/bin/ceph-osd --get-device-fsid /dev/zd16p2
Oct 31 01:14:05 perun.gaea.mythicnet.org sh[27999]: get_space_osd_uuid: Block /dev/zd16p2 has OSD UUID 00000000-0000-0000-0000-000000000000
Oct 31 01:14:05 perun.gaea.mythicnet.org sh[27999]: main_activate_space: activate: OSD device not present, not starting, yet
Oct 31 01:14:05 perun.gaea.mythicnet.org systemd[1]: Started Ceph disk activation: /dev/zd16p2.
Oct 31 01:14:05 perun.gaea.mythicnet.org kernel: XFS (zd16p1): Mounting V5 Filesystem
Oct 31 01:14:05 perun.gaea.mythicnet.org kernel: XFS (zd16p1): Ending clean mount
Oct 31 01:14:05 perun.gaea.mythicnet.org kernel: XFS (zd16p1): Unmounting Filesystem
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: main_trigger: creating /var/lib/ceph/tmp/mnt.daheHB/keyring
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: added entity osd.1 auth auth(auid = 18446744073709551615 key=AQCdBvhZHBTaDxAALUgBdFADHRoAi5A5Zb0BaQ== with 0 caps)
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: main_trigger: main_activate: path = /dev/zd16p1
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: get_dm_uuid: get_dm_uuid /dev/zd16p1 uuid path is /sys/dev/block/230:17/dm/uuid
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: command: Running command: /sbin/blkid -o udev -p /dev/zd16p1
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: command: Running command: /sbin/blkid -p -s TYPE -o value -- /dev/zd16p1
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: command: Running command: /usr/bin/ceph-conf --cluster=ceph --name=osd. --lookup osd_mount_options_xfs
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: command: Running command: /usr/bin/ceph-conf --cluster=ceph --name=osd. --lookup osd_fs_mount_options_xfs
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: mount: Mounting /dev/zd16p1 on /var/lib/ceph/tmp/mnt.daheHB with options noatime,inode64
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: command_check_call: Running command: /bin/mount -t xfs -o noatime,inode64 -- /dev/zd16p1 /var/lib/ceph/tmp/mnt.daheHB
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: activate: Cluster uuid is 2b70b442-d912-4d6b-b9ad-b359b9339e4f
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: command: Running command: /usr/bin/ceph-osd --cluster=ceph --show-config-value=fsid
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: activate: Cluster name is ceph
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: activate: OSD uuid is f9242a92-09b1-458a-8dd9-124f3ce3e772
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: allocate_osd_id: Allocating OSD id...
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: command: Running command: /usr/bin/ceph-authtool --gen-print-key
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: __init__: stderr
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: command_with_stdin: Running command with stdin: ceph --cluster ceph --name client.bootstrap-osd --keyring /var/lib/ceph/bootstrap-osd/ceph.keyring -i - osd new f9242a92-09b1-458a-8dd9-124f3ce3e772
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: command_with_stdin: 1
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: command_check_call: Running command: /usr/bin/ceph-authtool /var/lib/ceph/tmp/mnt.daheHB/keyring --create-keyring --name osd.1 --add-key AQCdBvhZHBTaDxAALUgBdFADHRoAi5A5Zb0BaQ==
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: command: Running command: /bin/chown -R ceph:ceph /var/lib/ceph/tmp/mnt.daheHB/keyring
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: command: Running command: /bin/chown -R ceph:ceph /var/lib/ceph/tmp/mnt.daheHB/whoami.28065.tmp
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: activate: OSD id is 1
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: activate: Initializing OSD...
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: command_check_call: Running command: /usr/bin/ceph --cluster ceph --name client.bootstrap-osd --keyring /var/lib/ceph/bootstrap-osd/ceph.keyring mon getmap -o /var/lib/ceph/tmp/mnt.daheHB/activate.monmap
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: got monmap epoch 4
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: command_check_call: Running command: /usr/bin/ceph-osd --cluster ceph --mkfs -i 1 --monmap /var/lib/ceph/tmp/mnt.daheHB/activate.monmap --osd-data /var/lib/ceph/tmp/mnt.daheHB --osd-uuid f9242a92-09b1-458a-8dd9-124f3ce3e772 --setuser ceph --setgroup ceph
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: 2017-10-31 01:14:05.802275 7fca5d901e00 -1 bluestore(/var/lib/ceph/tmp/mnt.daheHB) _setup_block_symlink_or_file failed to open block file: (13) Permission denied
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: 2017-10-31 01:14:05.802299 7fca5d901e00 -1 bluestore(/var/lib/ceph/tmp/mnt.daheHB) mkfs failed, (13) Permission denied
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: 2017-10-31 01:14:05.802302 7fca5d901e00 -1 OSD::mkfs: ObjectStore::mkfs failed with error (13) Permission denied
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: 2017-10-31 01:14:05.802360 7fca5d901e00 -1 ** ERROR: error creating empty object store in /var/lib/ceph/tmp/mnt.daheHB: (13) Permission denied
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: mount_activate: Failed to activate
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: unmount: Unmounting /var/lib/ceph/tmp/mnt.daheHB
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: command_check_call: Running command: /bin/umount -- /var/lib/ceph/tmp/mnt.daheHB
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: Traceback (most recent call last):
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: File "/usr/sbin/ceph-disk", line 11, in <module>
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: load_entry_point('ceph-disk==1.0.0', 'console_scripts', 'ceph-disk')()
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: File "/usr/lib/python2.7/dist-packages/ceph_disk/main.py", line 5704, in run
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: main(sys.argv[1:])
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: File "/usr/lib/python2.7/dist-packages/ceph_disk/main.py", line 5655, in main
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: args.func(args)
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: File "/usr/lib/python2.7/dist-packages/ceph_disk/main.py", line 3759, in main_activate
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: reactivate=args.reactivate,
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: File "/usr/lib/python2.7/dist-packages/ceph_disk/main.py", line 3522, in mount_activate
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: (osd_id, cluster) = activate(path, activate_key_template, init)
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: File "/usr/lib/python2.7/dist-packages/ceph_disk/main.py", line 3699, in activate
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: keyring=keyring,
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: File "/usr/lib/python2.7/dist-packages/ceph_disk/main.py", line 3151, in mkfs
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: '--setgroup', get_ceph_group(),
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: File "/usr/lib/python2.7/dist-packages/ceph_disk/main.py", line 558, in command_check_call
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: return subprocess.check_call(arguments)
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: File "/usr/lib/python2.7/subprocess.py", line 186, in check_call
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: raise CalledProcessError(retcode, cmd)
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: subprocess.CalledProcessError: Command '['/usr/bin/ceph-osd', '--cluster', 'ceph', '--mkfs', '-i', u'1', '--monmap', '/var/lib/ceph/tmp/mnt.daheHB/activate.monmap', '--osd-data', '/var/lib/ceph/tmp/mnt.daheHB', '--osd-uuid', u'f9242a92-09b1-458a-8dd9-124f3ce3e772'
, '--setuser', 'ceph', '--setgroup', 'ceph']' returned non-zero exit status 1
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: Traceback (most recent call last):
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: File "/usr/sbin/ceph-disk", line 11, in <module>
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: load_entry_point('ceph-disk==1.0.0', 'console_scripts', 'ceph-disk')()
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: File "/usr/lib/python2.7/dist-packages/ceph_disk/main.py", line 5704, in run
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: main(sys.argv[1:])
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: File "/usr/lib/python2.7/dist-packages/ceph_disk/main.py", line 5655, in main
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: args.func(args)
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: File "/usr/lib/python2.7/dist-packages/ceph_disk/main.py", line 4858, in main_trigger
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: raise Error('return code ' + str(ret))
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28008]: ceph_disk.main.Error: Error: return code 1
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28073]: main_trigger: main_trigger: Namespace(cluster='ceph', dev='/dev/zd16p1', dmcrypt=None, dmcrypt_key_dir='/etc/ceph/dmcrypt-keys', func=<function main_trigger at 0x7f25d0493de8>, log_stdout=True, prepend_to_path='/usr/bin', prog='ceph-disk', setgroup=None, setuser=N
one, statedir='/var/lib/ceph', sync=True, sysconfdir='/etc/ceph', verbose=True)
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28073]: command: Running command: /sbin/init --version
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28073]: command_check_call: Running command: /bin/chown ceph:ceph /dev/zd16p1
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28073]: command: Running command: /sbin/blkid -o udev -p /dev/zd16p1
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28073]: command: Running command: /sbin/blkid -o udev -p /dev/zd16p1
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28073]: main_trigger: trigger /dev/zd16p1 parttype 4fbd7e29-9d25-41b8-afd0-062c0ceff05d uuid f9242a92-09b1-458a-8dd9-124f3ce3e772
Oct 31 01:14:08 perun.gaea.mythicnet.org sh[28073]: command: Running command: /usr/sbin/ceph-disk --verbose activate /dev/zd16p1
Oct 31 01:14:08 perun.gaea.mythicnet.org kernel: XFS (zd16p1): Mounting V5 Filesystem
Oct 31 01:14:08 perun.gaea.mythicnet.org kernel: XFS (zd16p1): Ending clean mount
Oct 31 01:14:08 perun.gaea.mythicnet.org kernel: XFS (zd16p1): Unmounting Filesystem
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: main_trigger:
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: main_trigger: main_activate: path = /dev/zd16p1
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: get_dm_uuid: get_dm_uuid /dev/zd16p1 uuid path is /sys/dev/block/230:17/dm/uuid
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: command: Running command: /sbin/blkid -o udev -p /dev/zd16p1
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: command: Running command: /sbin/blkid -p -s TYPE -o value -- /dev/zd16p1
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: command: Running command: /usr/bin/ceph-conf --cluster=ceph --name=osd. --lookup osd_mount_options_xfs
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: command: Running command: /usr/bin/ceph-conf --cluster=ceph --name=osd. --lookup osd_fs_mount_options_xfs
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: mount: Mounting /dev/zd16p1 on /var/lib/ceph/tmp/mnt.glX0YH with options noatime,inode64
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: command_check_call: Running command: /bin/mount -t xfs -o noatime,inode64 -- /dev/zd16p1 /var/lib/ceph/tmp/mnt.glX0YH
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: activate: Cluster uuid is 2b70b442-d912-4d6b-b9ad-b359b9339e4f
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: command: Running command: /usr/bin/ceph-osd --cluster=ceph --show-config-value=fsid
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: activate: Cluster name is ceph
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: activate: OSD uuid is f9242a92-09b1-458a-8dd9-124f3ce3e772
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: activate: OSD id is 1
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: activate: Initializing OSD...
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: command_check_call: Running command: /usr/bin/ceph --cluster ceph --name client.bootstrap-osd --keyring /var/lib/ceph/bootstrap-osd/ceph.keyring mon getmap -o /var/lib/ceph/tmp/mnt.glX0YH/activate.monmap
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: got monmap epoch 4
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: command_check_call: Running command: /usr/bin/ceph-osd --cluster ceph --mkfs -i 1 --monmap /var/lib/ceph/tmp/mnt.glX0YH/activate.monmap --osd-data /var/lib/ceph/tmp/mnt.glX0YH --osd-uuid f9242a92-09b1-458a-8dd9-124f3ce3e772 --setuser ceph --setgroup ceph
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: 2017-10-31 01:14:08.698405 7f2fe237be00 -1 bluestore(/var/lib/ceph/tmp/mnt.glX0YH) _setup_block_symlink_or_file failed to open block file: (13) Permission denied
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: 2017-10-31 01:14:08.698439 7f2fe237be00 -1 bluestore(/var/lib/ceph/tmp/mnt.glX0YH) mkfs failed, (13) Permission denied
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: 2017-10-31 01:14:08.698441 7f2fe237be00 -1 OSD::mkfs: ObjectStore::mkfs failed with error (13) Permission denied
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: 2017-10-31 01:14:08.698503 7f2fe237be00 -1 ** ERROR: error creating empty object store in /var/lib/ceph/tmp/mnt.glX0YH: (13) Permission denied
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: mount_activate: Failed to activate
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: unmount: Unmounting /var/lib/ceph/tmp/mnt.glX0YH
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: command_check_call: Running command: /bin/umount -- /var/lib/ceph/tmp/mnt.glX0YH
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: Traceback (most recent call last):
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: File "/usr/sbin/ceph-disk", line 11, in <module>
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: load_entry_point('ceph-disk==1.0.0', 'console_scripts', 'ceph-disk')()
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: File "/usr/lib/python2.7/dist-packages/ceph_disk/main.py", line 5704, in run
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: main(sys.argv[1:])
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: File "/usr/lib/python2.7/dist-packages/ceph_disk/main.py", line 5655, in main
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: args.func(args)
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: File "/usr/lib/python2.7/dist-packages/ceph_disk/main.py", line 3759, in main_activate
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: reactivate=args.reactivate,
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: File "/usr/lib/python2.7/dist-packages/ceph_disk/main.py", line 3522, in mount_activate
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: (osd_id, cluster) = activate(path, activate_key_template, init)
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: File "/usr/lib/python2.7/dist-packages/ceph_disk/main.py", line 3699, in activate
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: keyring=keyring,
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: File "/usr/lib/python2.7/dist-packages/ceph_disk/main.py", line 3151, in mkfs
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: '--setgroup', get_ceph_group(),
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: File "/usr/lib/python2.7/dist-packages/ceph_disk/main.py", line 558, in command_check_call
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: return subprocess.check_call(arguments)
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: File "/usr/lib/python2.7/subprocess.py", line 186, in check_call
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: raise CalledProcessError(retcode, cmd)
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: subprocess.CalledProcessError: Command '['/usr/bin/ceph-osd', '--cluster', 'ceph', '--mkfs', '-i', u'1', '--monmap', '/var/lib/ceph/tmp/mnt.glX0YH/activate.monmap', '--osd-data', '/var/lib/ceph/tmp/mnt.glX0YH', '--osd-uuid', u'f9242a92-09b1-458a-8dd9-124f3ce3e772'
, '--setuser', 'ceph', '--setgroup', 'ceph']' returned non-zero exit status 1
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: Traceback (most recent call last):
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: File "/usr/sbin/ceph-disk", line 11, in <module>
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: load_entry_point('ceph-disk==1.0.0', 'console_scripts', 'ceph-disk')()
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: File "/usr/lib/python2.7/dist-packages/ceph_disk/main.py", line 5704, in run
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: main(sys.argv[1:])
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: File "/usr/lib/python2.7/dist-packages/ceph_disk/main.py", line 5655, in main
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: args.func(args)
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: File "/usr/lib/python2.7/dist-packages/ceph_disk/main.py", line 4858, in main_trigger
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: raise Error('return code ' + str(ret))
Oct 31 01:14:11 perun.gaea.mythicnet.org sh[28073]: ceph_disk.main.Error: Error: return code 1
Oct 31 01:14:11 perun.gaea.mythicnet.org systemd[1]: ceph-disk@dev-zd16p1.service: Main process exited, code=exited, status=1/FAILURE
Oct 31 01:14:11 perun.gaea.mythicnet.org systemd[1]: Failed to start Ceph disk activation: /dev/zd16p1.
Oct 31 01:14:11 perun.gaea.mythicnet.org systemd[1]: ceph-disk@dev-zd16p1.service: Unit entered failed state.
Oct 31 01:14:11 perun.gaea.mythicnet.org systemd[1]: ceph-disk@dev-zd16p1.service: Failed with result 'exit-code'.
I noticed there are several issues with incorrect permissions on block devices with older versions of Ceph so I checked:
Code:
root@perun:/var/lib/ceph# ls -la /dev/zd16*
brw-rw---- 1 root disk 230, 16 Oct 31 01:14 /dev/zd16
brw-rw---- 1 ceph ceph 230, 17 Oct 31 01:14 /dev/zd16p1
brw-rw---- 1 ceph ceph 230, 18 Oct 31 01:14 /dev/zd16p2
However, /var/lib/ceph/tmp is mysteriously owned by root. Perhaps it's related to issue 21068 on the Ceph bugtracker. I don't know enough about the internals of Ceph to be able to really tell and I don't see a reference to the block symlink although it's clearly trying to create one.
Versions:
Code:
root@perun:/var/lib/ceph# pveversion --verbose
proxmox-ve: 5.1-25 (running kernel: 4.13.4-1-pve)
pve-manager: 5.1-36 (running version: 5.1-36/131401db)
pve-kernel-4.4.83-1-pve: 4.4.83-96
pve-kernel-4.13.4-1-pve: 4.13.4-25
pve-kernel-4.4.49-1-pve: 4.4.49-86
pve-kernel-4.4.35-1-pve: 4.4.35-77
pve-kernel-4.4.44-1-pve: 4.4.44-84
libpve-http-server-perl: 2.0-6
lvm2: 2.02.168-pve6
corosync: 2.4.2-pve3
libqb0: 1.0.1-1
pve-cluster: 5.0-15
qemu-server: 5.0-17
pve-firmware: 2.0-3
libpve-common-perl: 5.0-20
libpve-guest-common-perl: 2.0-13
libpve-access-control: 5.0-7
libpve-storage-perl: 5.0-16
pve-libspice-server1: 0.12.8-3
vncterm: 1.5-2
pve-docs: 5.1-12
pve-qemu-kvm: 2.9.1-2
pve-container: 2.0-17
pve-firewall: 3.0-3
pve-ha-manager: 2.0-3
ksm-control-daemon: 1.2-2
glusterfs-client: 3.8.8-1
lxc-pve: 2.1.0-2
lxcfs: 2.0.7-pve4
criu: 2.11.1-1~bpo90
novnc-pve: 0.6-4
smartmontools: 6.5+svn4324-1
zfsutils-linux: 0.7.2-pve1~bpo90
ceph: 12.2.1-1~bpo90+1
Code:
root@perun:/var/lib/ceph# uname -a
Linux perun.gaea.mythicnet.org 4.13.4-1-pve #1 SMP PVE 4.13.4-25 (Fri, 13 Oct 2017 08:59:53 +0200) x86_64 GNU/Linux
Last edited: