I'm seeing a problem with OSD startup on our centos7.3 / jewel 10.2.7
cluster.
Each storage node has 24 HDD OSDs with journal on NVME, and 6 SSD osds -
all 30 osds set up with dmcrypt.
What I see is that on reboot, not all the OSDs start up successfully -
usually ~24 out of 30 start.
Manually prodding udev with:
udevadm trigger --subsystem-match=block --action=add
generally gets all the missing OSDs added.
I do see failed ceph-disk@device.service logs, which then succeed on
second attempt, after the "udevadm trigger".
It looks like the problem is with ceph-disk trying to look up the
dmcrypt key, it seems to erroneously have "key-management-mode None".
Here's an example failure followed by subsequent success.:
# journalctl _SYSTEMD_UNIT=ceph-disk@dev-sdy1.service
-- Logs begin at Tue 2017-07-11 16:58:00 CDT, end at Tue 2017-07-11 17:20:01
CDT. --
Jul 11 16:58:09 hostname sh[2230]: main_trigger: main_trigger:
Namespace(cluster='ceph', dev='/dev/sdy1', dmcrypt=None,
dmcrypt_key_dir='/etc/ceph/dmcrypt-keys', func=<function main_trigger at
0xb340c8>, log_stdout=True, prepend_to_path='/usr/bin', prog='ceph-disk',
setgroup=Non
e, setuser=None, statedir='/var/lib/ceph', sync=True, sysconfdir='/etc/ceph',
verbose=True)
Jul 11 16:58:09 hostname sh[2230]: command: Running command: /usr/sbin/init
--version
Jul 11 16:58:09 hostname sh[2230]: command_check_call: Running command:
/usr/bin/chown ceph:ceph /dev/sdy1
Jul 11 16:58:09 hostname sh[2230]: command: Running command: /usr/sbin/blkid -o
udev -p /dev/sdy1
Jul 11 16:58:09 hostname sh[2230]: command: Running command: /usr/sbin/blkid -o
udev -p /dev/sdy1
Jul 11 16:58:09 hostname sh[2230]: main_trigger: trigger /dev/sdy1 parttype
4fbd7e29-9d25-41b8-afd0-35865ceff05d uuid 5a0602c7-224d-4a12-884a-58e5dc9a87e9
Jul 11 16:58:09 hostname sh[2230]: command: Running command:
/usr/sbin/ceph-disk --verbose activate --dmcrypt /dev/sdy1
Jul 11 16:58:13 hostname python[2881]: detected unhandled Python exception in
'/usr/sbin/ceph-disk'
Jul 11 16:58:13 hostname sh[2230]: main_trigger:
Jul 11 16:58:13 hostname sh[2230]: main_trigger: main_activate: path = /dev/sdy1
Jul 11 16:58:13 hostname sh[2230]: get_dm_uuid: get_dm_uuid /dev/sdy1 uuid path
is /sys/dev/block/65:129/dm/uuid
Jul 11 16:58:13 hostname sh[2230]: command: Running command: /usr/sbin/blkid -o
udev -p /dev/sdy1
Jul 11 16:58:13 hostname sh[2230]: command: Running command: /usr/sbin/blkid -o
udev -p /dev/sdy1
Jul 11 16:58:13 hostname sh[2230]: command: Running command: /usr/sbin/blkid -o
udev -p /dev/sdy1
Jul 11 16:58:13 hostname sh[2230]: command: Running command: /usr/sbin/blkid -o
udev -p /dev/sdy1
Jul 11 16:58:13 hostname sh[2230]: Traceback (most recent call last):
Jul 11 16:58:13 hostname sh[2230]: File "/usr/sbin/ceph-disk", line 9, in
<module>
Jul 11 16:58:13 hostname sh[2230]: load_entry_point('ceph-disk==1.0.0',
'console_scripts', 'ceph-disk')()
Jul 11 16:58:13 hostname sh[2230]: File
"/usr/lib/python2.7/site-packages/ceph_disk/main.py", line 5047, in run
Jul 11 16:58:13 hostname sh[2230]: main(sys.argv[1:])
Jul 11 16:58:13 hostname sh[2230]: File
"/usr/lib/python2.7/site-packages/ceph_disk/main.py", line 4998, in main
Jul 11 16:58:13 hostname sh[2230]: args.func(args)
Jul 11 16:58:13 hostname sh[2230]: File
"/usr/lib/python2.7/site-packages/ceph_disk/main.py", line 3357, in
main_activate
Jul 11 16:58:13 hostname sh[2230]: reactivate=args.reactivate,
Jul 11 16:58:13 hostname sh[2230]: File
"/usr/lib/python2.7/site-packages/ceph_disk/main.py", line 3059, in
mount_activate
Jul 11 16:58:13 hostname sh[2230]: dev = dmcrypt_map(dev, dmcrypt_key_dir)
Jul 11 16:58:13 hostname sh[2230]: File
"/usr/lib/python2.7/site-packages/ceph_disk/main.py", line 3037, in dmcrypt_map
Jul 11 16:58:13 hostname sh[2230]: dmcrypt_key = get_dmcrypt_key(part_uuid,
dmcrypt_key_dir, luks)
Jul 11 16:58:13 hostname sh[2230]: File
"/usr/lib/python2.7/site-packages/ceph_disk/main.py", line 1156, in
get_dmcrypt_key
Jul 11 16:58:13 hostname sh[2230]: raise Error('unknown key-management-mode ' +
str(mode))
Jul 11 16:58:13 hostname sh[2230]: ceph_disk.main.Error: Error: unknown
key-management-mode None
Jul 11 16:58:13 hostname python[2259]: detected unhandled Python exception in
'/usr/sbin/ceph-disk'
Jul 11 16:58:14 hostname sh[2230]: Traceback (most recent call last):
Jul 11 16:58:14 hostname sh[2230]: File "/usr/sbin/ceph-disk", line 9, in
<module>
Jul 11 16:58:14 hostname sh[2230]: load_entry_point('ceph-disk==1.0.0',
'console_scripts', 'ceph-disk')()
Jul 11 16:58:14 hostname sh[2230]: File
"/usr/lib/python2.7/site-packages/ceph_disk/main.py", line 5047, in run
Jul 11 16:58:14 hostname sh[2230]: main(sys.argv[1:])
Jul 11 16:58:14 hostname sh[2230]: File
"/usr/lib/python2.7/site-packages/ceph_disk/main.py", line 4998, in main
Jul 11 16:58:14 hostname sh[2230]: args.func(args)
Jul 11 16:58:14 hostname sh[2230]: File
"/usr/lib/python2.7/site-packages/ceph_disk/main.py", line 4435, in main_trigger
Jul 11 16:58:14 hostname sh[2230]: raise Error('return code ' + str(ret))
Jul 11 16:58:14 hostname sh[2230]: ceph_disk.main.Error: Error: return code 1
then after udevadm trigger...
Jul 11 17:15:18 hostname sh[40835]: main_trigger: main_trigger:
Namespace(cluster='ceph', dev='/dev/sdy1', dmcrypt=None,
dmcrypt_key_dir='/etc/ceph/dmcrypt-keys', func=<function main_trigger at
0x1ddd0c8>, log_stdout=True, prepend_to_path='/usr/bin', prog='ceph-disk',
setgroup=N
one, setuser=None, statedir='/var/lib/ceph', sync=True, sysconfdir='/etc/ceph',
verbose=True)
Jul 11 17:15:18 hostname sh[40835]: command: Running command: /usr/sbin/init
--version
Jul 11 17:15:18 hostname sh[40835]: command_check_call: Running command:
/usr/bin/chown ceph:ceph /dev/sdy1
Jul 11 17:15:18 hostname sh[40835]: command: Running command: /usr/sbin/blkid
-o udev -p /dev/sdy1
Jul 11 17:15:18 hostname sh[40835]: command: Running command: /usr/sbin/blkid
-o udev -p /dev/sdy1
Jul 11 17:15:18 hostname sh[40835]: main_trigger: trigger /dev/sdy1 parttype
4fbd7e29-9d25-41b8-afd0-35865ceff05d uuid 5a0602c7-224d-4a12-884a-58e5dc9a87e9
Jul 11 17:15:18 hostname sh[40835]: command: Running command:
/usr/sbin/ceph-disk --verbose activate --dmcrypt /dev/sdy1
Jul 11 17:15:22 hostname sh[40835]: main_trigger:
Jul 11 17:15:22 hostname sh[40835]: main_trigger: main_activate: path =
/dev/sdy1
Jul 11 17:15:22 hostname sh[40835]: get_dm_uuid: get_dm_uuid /dev/sdy1 uuid
path is /sys/dev/block/65:129/dm/uuid
Jul 11 17:15:22 hostname sh[40835]: command: Running command: /usr/sbin/blkid
-o udev -p /dev/sdy1
Jul 11 17:15:22 hostname sh[40835]: command: Running command: /usr/sbin/blkid
-o udev -p /dev/sdy1
Jul 11 17:15:22 hostname sh[40835]: command: Running command: /usr/sbin/blkid
-o udev -p /dev/sdy1
Jul 11 17:15:22 hostname sh[40835]: command: Running command: /usr/sbin/blkid
-o udev -p /dev/sdy1
Jul 11 17:15:22 hostname sh[40835]: command: Running command: /usr/bin/ceph
--name client.osd-lockbox.5a0602c7-224d-4a12-884a-58e5dc9a87e9 --keyring
/var/lib/ceph/osd-lockbox/5a0602c7-224d-4a12-884a-58e5dc9a87e9/keyring
config-key get dm-crypt/osd/5a0602c7-224d-4a12-884a-58e5dc9
a87e9/luks
Jul 11 17:15:22 hostname sh[40835]: get_dmcrypt_key: stderr obtained
'dm-crypt/osd/5a0602c7-224d-4a12-884a-58e5dc9a87e9/luks'
Jul 11 17:15:22 hostname sh[40835]: command: Running command: /sbin/blkid -p -s
TYPE -o value -- /dev/mapper/5a0602c7-224d-4a12-884a-58e5dc9a87e9
Jul 11 17:15:22 hostname sh[40835]: command: Running command:
/usr/bin/ceph-conf --cluster=ceph --name=osd. --lookup osd_mount_options_xfs
Jul 11 17:15:22 hostname sh[40835]: command: Running command:
/usr/bin/ceph-conf --cluster=ceph --name=osd. --lookup osd_fs_mount_options_xfs
Jul 11 17:15:22 hostname sh[40835]: mount: Mounting
/dev/mapper/5a0602c7-224d-4a12-884a-58e5dc9a87e9 on
/var/lib/ceph/tmp/mnt.8p16zB with options noatime,inode64
Jul 11 17:15:22 hostname sh[40835]: command_check_call: Running command:
/usr/bin/mount -t xfs -o noatime,inode64 --
/dev/mapper/5a0602c7-224d-4a12-884a-58e5dc9a87e9 /var/lib/ceph/tmp/mnt.8p16zB
Jul 11 17:15:22 hostname sh[40835]: command: Running command:
/usr/sbin/restorecon /var/lib/ceph/tmp/mnt.8p16zB
Jul 11 17:15:22 hostname sh[40835]: activate: Cluster uuid is
6524867b-6824-4d20-aec8-414f1bd3ed62
Jul 11 17:15:22 hostname sh[40835]: command: Running command: /usr/bin/ceph-osd
--cluster=ceph --show-config-value=fsid
Jul 11 17:15:22 hostname sh[40835]: activate: Cluster name is ceph
Jul 11 17:15:22 hostname sh[40835]: activate: OSD uuid is
5a0602c7-224d-4a12-884a-58e5dc9a87e9
Jul 11 17:15:22 hostname sh[40835]: activate: OSD id is 24
Jul 11 17:15:22 hostname sh[40835]: command: Running command:
/usr/bin/ceph-conf --cluster=ceph --name=osd. --lookup init
Jul 11 17:15:22 hostname sh[40835]: command: Running command:
/usr/bin/ceph-detect-init --default sysvinit
Jul 11 17:15:22 hostname sh[40835]: activate: Marking with init system systemd
Jul 11 17:15:22 hostname sh[40835]: command: Running command:
/usr/sbin/restorecon -R /var/lib/ceph/tmp/mnt.8p16zB/systemd
Jul 11 17:15:22 hostname sh[40835]: command: Running command: /usr/bin/chown -R
ceph:ceph /var/lib/ceph/tmp/mnt.8p16zB/systemd
Jul 11 17:15:22 hostname sh[40835]: activate: ceph osd.24 data dir is ready at
/var/lib/ceph/tmp/mnt.8p16zB
Jul 11 17:15:22 hostname sh[40835]: mount_activate: ceph osd.24 already mounted
in position; unmounting ours.
Jul 11 17:15:22 hostname sh[40835]: unmount: Unmounting
/var/lib/ceph/tmp/mnt.8p16zB
Jul 11 17:15:22 hostname sh[40835]: command_check_call: Running command:
/bin/umount -- /var/lib/ceph/tmp/mnt.8p16zB
Jul 11 17:15:22 hostname sh[40835]: start_daemon: Starting ceph osd.24...
Jul 11 17:15:22 hostname sh[40835]: command_check_call: Running command:
/usr/bin/systemctl disable ceph-osd@24
Jul 11 17:15:22 hostname sh[40835]: command_check_call: Running command:
/usr/bin/systemctl enable --runtime ceph-osd@24
Jul 11 17:15:22 hostname sh[40835]: command_check_call: Running command:
/usr/bin/systemctl start ceph-osd@24
I guess the initial error (key-management-mode None) could be caused by
failing to read data from the osd-lockbox partition. Querying journalctl
about that partition does suggest a timing issue - the lockbox temporary
mount doesn't happen until 16:59:23, which is after the 16:58:13 attempt
to fetch the dmcrypt key for /dev/sdy1:
# journalctl _SYSTEMD_UNIT=ceph-disk@dev-sdy3.service
-- Logs begin at Tue 2017-07-11 16:58:00 CDT, end at Tue 2017-07-11 17:20:01
CDT. --
Jul 11 16:58:12 hostname sh[2536]: main_trigger: main_trigger:
Namespace(cluster='ceph', dev='/dev/sdy3', dmcrypt=None,
dmcrypt_key_dir='/etc/ceph/dmcrypt-keys', func=<function main_trigger at
0x25730c8>, log_stdout=True, prepend_to_path='/usr/bin', prog='ceph-disk',
setgroup=None, setuser=None, statedir='/var/lib/ceph', sync=True,
sysconfdir='/etc/ceph', verbose=True)
Jul 11 16:58:12 hostname sh[2536]: command: Running command: /usr/sbin/init
--version
Jul 11 16:58:12 hostname sh[2536]: command_check_call: Running command:
/usr/bin/chown ceph:ceph /dev/sdy3
Jul 11 16:58:12 hostname sh[2536]: command: Running command: /usr/sbin/blkid -o
udev -p /dev/sdy3
Jul 11 16:58:12 hostname sh[2536]: command: Running command: /usr/sbin/blkid -o
udev -p /dev/sdy3
Jul 11 16:58:12 hostname sh[2536]: main_trigger: trigger /dev/sdy3 parttype
fb3aabf9-d25f-47cc-bf5e-721d1816496b uuid 00000000-0000-0000-0000-000000000000
Jul 11 16:58:12 hostname sh[2536]: command: Running command:
/usr/sbin/ceph-disk --verbose activate-lockbox /dev/sdy3
Jul 11 16:59:23 hostname sh[2536]: main_trigger:
Jul 11 16:59:23 hostname sh[2536]: main_trigger: get_dm_uuid: get_dm_uuid
/dev/sdy3 uuid path is /sys/dev/block/65:131/dm/uuid
Jul 11 16:59:23 hostname sh[2536]: activate: Mounting lockbox temporarily mount
-t ext4 -o ro /dev/sdy3 /var/lib/ceph/tmp/mnt.2_x1p1
Jul 11 16:59:23 hostname sh[2536]: command_check_call: Running command:
/usr/bin/mount -t ext4 -o ro /dev/sdy3 /var/lib/ceph/tmp/mnt.2_x1p1
Jul 11 16:59:23 hostname sh[2536]: command_check_call: Running command:
/usr/bin/umount /var/lib/ceph/tmp/mnt.2_x1p1
Jul 11 16:59:23 hostname sh[2536]: activate: Mounting lockbox readonly
/usr/bin/mount -t ext4 -o ro /dev/sdy3 /var/lib/ceph/tmp/mnt.2_x1p1
Jul 11 16:59:23 hostname sh[2536]: command_check_call: Running command:
/usr/bin/mount -t ext4 -o ro /dev/sdy3
/var/lib/ceph/osd-lockbox/5a0602c7-224d-4a12-884a-58e5dc9a87e9
Jul 11 16:59:23 hostname sh[2536]: command_check_call: Running command:
/usr/sbin/ceph-disk trigger
/dev/disk/by-partuuid/b281e645-a3aa-43ac-945b-769b7438f2c1
Jul 11 16:59:23 hostname sh[2536]: command_check_call: Running command:
/usr/sbin/ceph-disk trigger
/dev/disk/by-partuuid/5a0602c7-224d-4a12-884a-58e5dc9a87e9
Jul 11 17:15:18 hostname sh[40830]: main_trigger: main_trigger:
Namespace(cluster='ceph', dev='/dev/sdy3', dmcrypt=None,
dmcrypt_key_dir='/etc/ceph/dmcrypt-keys', func=<function main_trigger at
0x10550c8>, log_stdout=True, prepend_to_path='/usr/bin', prog='ceph-disk',
setgroup=None, setuser=None, statedir='/var/lib/ceph', sync=True,
sysconfdir='/etc/ceph', verbose=True)
Jul 11 17:15:18 hostname sh[40830]: command: Running command: /usr/sbin/init
--version
Jul 11 17:15:18 hostname sh[40830]: command_check_call: Running command:
/usr/bin/chown ceph:ceph /dev/sdy3
Jul 11 17:15:18 hostname sh[40830]: command: Running command: /usr/sbin/blkid
-o udev -p /dev/sdy3
Jul 11 17:15:18 hostname sh[40830]: command: Running command: /usr/sbin/blkid
-o udev -p /dev/sdy3
Jul 11 17:15:18 hostname sh[40830]: main_trigger: trigger /dev/sdy3 parttype
fb3aabf9-d25f-47cc-bf5e-721d1816496b uuid 00000000-0000-0000-0000-000000000000
Jul 11 17:15:18 hostname sh[40830]: command: Running command:
/usr/sbin/ceph-disk --verbose activate-lockbox /dev/sdy3
Jul 11 17:15:20 hostname sh[40830]: main_trigger:
Jul 11 17:15:20 hostname sh[40830]: main_trigger: get_dm_uuid: get_dm_uuid
/dev/sdy3 uuid path is /sys/dev/block/65:131/dm/uuid
Jul 11 17:15:20 hostname sh[40830]: activate: Lockbox already mounted at
/var/lib/ceph/osd-lockbox/5a0602c7-224d-4a12-884a-58e5dc9a87e9
So it seems like some kind of race condition. It does happen
consistently at reboot for all these systems, though the particular OSDs
affected change each time.
Any ideas how to troubleshoot further... or should I open a bug report?
Thanks!
Graham
--
Graham Allan
Minnesota Supercomputing Institute - g...@umn.edu
_______________________________________________
ceph-users mailing list
ceph-users@lists.ceph.com
http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com
