Ceph osd process was not recovered after lock and unlock on storage node with journal disk

Marking as release gating; appears related to ceph and requires further investigation.

I checked storage-0 lock and unlock, with BUILD_ID="20190528T202529Z". After unlock, storage-0 could will turn to available with no error, check uploaded attachment.

This is reproduced in the same lab in WR, the storage node that failed has journal disk configured just fyi.

storage-0:/home/wrsroot# /etc/init.d/ceph status
=== mon.storage-0 ===
{"version":"13.2.2","release":"mimic","release_type":"stable"}
mon.storage-0: running.
=== osd.0 ===
osd.0: not running.
=== osd.1 ===
osd.1: not running.
storage-0:/home/wrsroot#
storage-0:/home/wrsroot# /etc/init.d/ceph stop
=== osd.1 ===
storage-0:/home/wrsroot# /etc/init.d/ceph stop
=== osd.1 ===
Stopping Ceph osd.1 on storage-0...done
=== osd.0 ===
2019-05-30 17:58:23.946 7efc5f5751c0 -1 journal FileJournal::open: ondisk fsid 00000000-0000-0000-0000-000000000000 doesn't match expected f89591cf-a74f-4cff-85ed-8f93103267e0, invalid (someone else's?) journal
2019-05-30 17:58:23.946 7efc5f5751c0 -1 filestore(/var/lib/ceph/osd/ceph-1) mount(1871): failed to open journal /var/lib/ceph/osd/ceph-1/journal: (22) Invalid argument
2019-05-30 17:58:23.947 7efc5f5751c0 -1 ** ERROR: error flushing journal /var/lib/ceph/osd/ceph-1/journal for object store /var/lib/ceph/osd/ceph-1: (22) Invalid argument
Stopping Ceph osd.0 on storage-0...done
=== mon.storage-0 ===
2019-05-30 17:58:24.105 7f7d57a5e1c0 -1 journal FileJournal::open: ondisk fsid 00000000-0000-0000-0000-000000000000 doesn't match expected 6a6674e1-3450-4b0e-9618-b414bffff153, invalid (someone else's?) journal
2019-05-30 17:58:24.105 7f7d57a5e1c0 -1 filestore(/var/lib/ceph/osd/ceph-0) mount(1871): failed to open journal /var/lib/ceph/osd/ceph-0/journal: (22) Invalid argument
2019-05-30 17:58:24.105 7f7d57a5e1c0 -1 ** ERROR: error donehing journal /var/lib/ceph/osd/ceph-0/journal for object store /var/lib/ceph/osd/ceph-0: (22) Invalid argument
storage-0:/home/wrsroot# /etc/init.d/ceph stopl 31770...
=== osd.1 ===
Stopping Ceph osd.1 on storage-0...done
=== osd.0 ===
2019-05-30 18:00:15.760 7f70637011c0 -1 journal FileJournal::open: ondisk fsid 00000000-0000-0000-0000-000000000000 doesn't match expected f89591cf-a74f-4cff-85ed-8f93103267e0, invalid (someone else's?) journal
2019-05-30 18:00:15.760 7f70637011c0 -1 filestore(/var/lib/ceph/osd/ceph-1) mount(1871): failed to open journal /var/lib/ceph/osd/ceph-1/journal: (22) Invalid argument
2019-05-30 18:00:15.761 7f70637011c0 -1 ** ERROR: error flushing journal /var/lib/ceph/osd/ceph-1/journal for object store /var/lib/ceph/osd/ceph-1: (22) Invalid argument
Stopping Ceph osd.0 on storage-0...done
=== mon.storage-0 ===
2019-05-30 18:00:15.923 7fcc881e71c0 -1 journal FileJournal::open: ondisk fsid 00000000-0000-0000-0000-000000000000 doesn't match expected 6a6674e1-3450-4b0e-9618-b414bffff153, invalid (someone else's?) journal
2019-05-30 18:00:15.923 7fcc881e71c0 -1 filestore(/var/lib/ceph/osd/ceph-0) mount(1871): failed to open journal /var/lib/ceph/osd/ceph-0/journal: (22) Invalid argument
2019-05-30 18:00:15.923 7fcc881e71c0 -1 ** ERROR: error flushing journal /var/lib/ceph/osd/ceph-0/journal for object store /var/lib/ceph/osd/ceph-0: (22) Invalid argument
Stopping Ceph mon.storage-0 on storage-0...kill 45253...
done

Was the journal device purged correctly and removed from any Ceph metadata on it?
There is similar issue in ceph community and to avoid is to ensure there are no partitions or signatures on the NVMe device.

difficult to reproduce and filestore will be replace with bluestore in ceph later release

@Yang, do you have a manual way to recover the node once it is in failure state?

if it can be recovered by a manual way, then we are OK with Medium; otherwise, we'd like to raise the priority to High.

No it is not recoverable, system needs to be reinstalled after that. And is 100% reproducible in WR environment.
I'm not sure if the journal device was purged successfully, but ceph was healthy on that storage node before lock/unlock. Any commands we can run to check?

Below is the configs of that node.
[sysadmin@controller-0 ~(keystone_admin)]$ system host-stor-list storage-0
+--------------------------------------+----------+-------+------------+--------------------------------------+-----------------------------------------------+----------------+------------------+-----------+
| uuid | function | osdid | state | idisk_uuid | journal_path | journal_node | journal_size_gib | tier_name |
+--------------------------------------+----------+-------+------------+--------------------------------------+-----------------------------------------------+----------------+------------------+-----------+
| 618b6370-792a-49e2-951a-ab9418179904 | journal | None | configured | d3a6d5a7-06db-47d0-a7b1-c24b19f6d584 | None | None | None | None |
| 73e40f40-d400-484c-858d-f53db7755ad9 | osd | 1 | configured | 29dce56f-dfbe-4127-a89c-5803fe5b18c8 | /dev/disk/by-path/pci-0000:84:00. | /dev/nvme1n1p2 | 1 | storage |
| | | | | | 0-nvme-1-part2 | | | |
| | | | | | | | | |
| d824517a-6d37-41a9-9c6d-750af02a510c | osd | 0 | configured | dbf30bdc-d25f-4f33-92be-c639b4a82b82 | /dev/disk/by-path/pci-0000:84:00. | /dev/nvme1n1p1 | 1 | storage |
| | | | | | 0-nvme-1-part1 | | | |
| | | | | | | | | |
+--------------------------------------+----------+-------+------------+--------------------------------------+-----------------------------------------------+----------------+------------------+-----------+

[sysadmin@controller-0 ~(keystone_admin)]$ system host-disk-list storage-0
ssh +--------------------------------------+--------------+---------+---------+-------+------------+-----+--------------+-------------------------------------------+
| uuid | device_node | device_ | device_ | size_ | available_ | rpm | serial_id | device_path |
| | | num | type | gib | gib | | | ...

HI Liu Yang

If you reproduce, please help to this firstly. Thanks.

"ls -l /var/lib/ceph/osd/ceph-0"
"ls -l /var/lib/ceph/osd/ceph-1"

And such info on storage node, in /tmp/puppet/hieradata/host.yaml

platform::ceph::osds::journal_config: {}
platform::ceph::osds::osd_config:
  stor-1:
    data_path: !!python/unicode '/dev/disk/by-path/pci-0000:00:03.0-ata-2.0-part1'
    disk_path: !!python/unicode '/dev/disk/by-path/pci-0000:00:03.0-ata-2.0'
    journal_path: !!python/unicode '/dev/disk/by-path/pci-0000:00:03.0-ata-2.0-part2'
    osd_id: 0
    osd_uuid: !!python/unicode '70b3ad94-94b1-437f-b85c-064d9a89ad68'
    tier_name: !!python/unicode 'storage'

make it high as the failure cannot be recovered according to Liu Yang.

It seems the issue logs is the same with https://bugs.launchpad.net/starlingx/+bug/1837242, but it is in nvme device.

Found out the provision steps are different from Martin - need to reproduce it from Shanghai lab. Martin is working on align w/ Yang's provision steps.

issue reproduce in shanghai, with storage node provision with this command

system host-stor-add storage-0 journal 7cbc9885-476c-4ad2-9058-466f1e0f9667
system host-stor-add storage-0 osd 46393030-acbf-43f4-8ca9-f705f65bf457 --tier-uuid 4c672ca9-7c4b-472a-b049-eac115c8aef9

$ system host-lock storage-0 -f

And quickly correct this file on active controller /opt/platform/puppet/<storage-0 ip>.yaml

platform::ceph::osds::osd_config:
  stor-2:
    data_path: !!python/unicode '/dev/disk/by-path/pci-0000:00:17.0-ata-6.0-part1'
    disk_path: !!python/unicode '/dev/disk/by-path/pci-0000:00:17.0-ata-6.0'
    journal_path: !!python/unicode '/dev/disk/by-path/pci-0000:00:17.0-ata-2.0-part1'
    osd_id: 0
    osd_uuid: !!python/unicode 'fa90317d-3a7e-40db-9459-097e17e1eb90'
    tier_name: !!python/unicode 'storage'

change to

platform::ceph::osds::osd_config:
  stor-2:
    data_path: !!python/unicode '/dev/disk/by-path/pci-0000:00:17.0-ata-6.0-part1'
    disk_path: !!python/unicode '/dev/disk/by-path/pci-0000:00:17.0-ata-6.0'
    journal_path: !!python/unicode '/dev/disk/by-path/pci-0000:00:17.0-ata-6.0-part2'
    osd_id: 0
    osd_uuid: !!python/unicode 'fa90317d-3a7e-40db-9459-097e17e1eb90'
    tier_name: !!python/unicode 'storage'

Then storage-0 will be available.

Should be storage-disk-path and journal path wrong in database, which is write in storage node provision command "system host-stor-add"

Will check host-stor-add command.

confirm in ceph.pp

    Ceph::Osd {
      cluster => $cluster_name,
      cluster_uuid => $cluster_uuid,
    }

miss journal setting.

Study how to get journal_path in osd_config and set to class ceph::osd

Hello, the problem is not a problem when calling Ceph::Osd with the right journal path. Question is: are the DB entries correct for all external journals on the node?

The process is more complex. Journal partitions are (1) created in the system then (2) each partition is associated with an OSD.

Journal partitions are created in puppet through:
class platform::ceph::osds(
  $osd_config = {},
  $journal_config = {},
) inherits ::platform::ceph::params {
    ...
    create_resources('platform_ceph_journal', $journal_config)
    ...
}

and are assigned to osd's thourgh:

define platform_ceph_osd(
  $osd_id,
  $osd_uuid,
  $disk_path,
  $data_path,
  $journal_path,
  $tier_name,
) {

...
  -> exec { "configure journal location ${name}":
    logoutput => true,
    command => template('platform/ceph.journal.location.erb')
  }
...
}

Check ceph.journal.location.erb on what's called to create the journals.

Now, the first step is to check if journals are configured correctly in the DB (they must be one after the other: part1, part2 ... partN in consecutive order with no overlapping), then check them to also be ok in hieradata.
If they are right you should look in the OSD mount folder (check mount | grep osd) and see where the journal symbolic link is pointing if they are pointing ok then 'everything' is ok here.

If this breaks on lock/unlock w/o us doing any configuration change then I can only suspect that somthing changed either in DB or in generated yamls.

So, given that the process is different there is no need to add journal in:
Ceph::Osd {
      cluster => $cluster_name,
      cluster_uuid => $cluster_uuid,
    }

And please don't change it as it should no longer create the default collocated journal partition on the OSD, which is still needed even if users configure external journals (for failback).

Hi Ovidiu

Yes, ceph.journal.location.erb will create journal disk. But when "ceph disk prepare", in such command as below. (the below command, all excerpt from execution of osd.pp)

ceph-disk --verbose --log-stdout prepare --filestore --cluster-uuid 2b7f8105-78f0-4660-b110-ca2b90cfb3de --osd-uuid 47779da5-36c3-49b9-96c9-912c1f6bb70a --osd-id 1 --fs-type xfs --zap-disk /dev/sdb $(readlink -f '')

as no journal disk specified, ceph-disk will crate /dev/sdb1 and /dev/sdb2, /dev/sdb2 as journal disk

Then
# mount /dev/sdb1 /var/lib/ceph/osd/ceph-1
# ceph-osd --id 1 --mkfs --mkkey --mkjournal # it will initialize /dev/sdb2 as journal disk, write journal head to /dev/sdb2
# ceph auth add osd.1 osd 'allow *' mon 'allow rwx' -i /var/lib/ceph/osd/ceph-1/keyring
# umount /var/lib/ceph/osd/ceph-1

# ceph-disk activated /dev/sdb1

Then "/usr/sbin/ceph-manage-journal location" in ceph.journal.location.erb to create /dev/sdc1 for journal partition. But journal header and keyring is no write to /dev/sdc1

So next time lock and unlock, /etc/init.d/ceph start. read /dev/sdc1 header, find header missing, with below error message.

2019-05-30 17:58:23.946 7efc5f5751c0 -1 journal FileJournal::open: ondisk fsid 00000000-0000-0000-0000-000000000000 doesn't match expected f89591cf-a74f-4cff-85ed-8f93103267e0, invalid (someone else's?) journal

Fix proposed to branch: master
Review: https://review.opendev.org/679185

Hi Chen,

Journal header should be repaired when ceph is started, unless something changed with Mimic, the message you see should be treated as a warning ( 2019-05-30 17:58:23.946 7efc5f5751c0 -1 journal FileJournal::open: ondisk fsid 00000000-0000-0000-0000-000000000000 doesn't match expected f89591cf-a74f-4cff-85ed-8f93103267e0, invalid (someone else's?) journal ).
The journal partition is empty, cheps-osd sees this and initializes it as journal =» OSD should start correctly. Question is, why does it sometimes fail? It starts correctly most of the time...

So, if DB/manifest entries are ok, and the proposed fix works when moving journal from collocated to external on an existing OSD, please check one more more thing: when adding a new OSD with external journal (do not unlock, add a new OSD, collocate it to /dev/sdc1, then unlock) will you still see /dev/sdb1 and /dev/sdb2? It has to be there as user should be able to fallback to collocated in case the journal drive breaks (this was a product requirement at the time of implementation).

Hi Ovidiu

Yes still see /dev/sdc2 and /dev/sdd2. For this time deploy /dev/sdb is journal disk.

storage-0:~$ ls /dev/sd*
/dev/sda /dev/sda1 /dev/sda2 /dev/sda3 /dev/sda4 /dev/sdb /dev/sdb1 /dev/sdb2 /dev/sdc /dev/sdc1 /dev/sdc2 /dev/sdd /dev/sdd1 /dev/sdd2

And for the first puppet apply, there is such error log. This is maybe your referred
"Error initializing journal node: /dev/sdb2 for osd id: 1 ceph-osd return code: 250 "

2019-08-30T06:23:29.879 ^[[0;36mDebug: 2019-08-30 06:23:29 +0000 Exec[configure journal location stor-22](provider=posix): Executing '/usr/sbin/ceph-manage-journal location '{"osdid": 1, "journal_path": "/dev/disk/by-path/pci-0000:00:17.0-ata-2.0-part2", "data_path": "/dev/disk/by-path/pci-0000:00:17.0-ata-6.0-part1"}''^[[0m
2019-08-30T06:23:29.881 ^[[0;36mDebug: 2019-08-30 06:23:29 +0000 Executing: '/usr/sbin/ceph-manage-journal location '{"osdid": 1, "journal_path": "/dev/disk/by-path/pci-0000:00:17.0-ata-2.0-part2", "data_path": "/dev/disk/by-path/pci-0000:00:17.0-ata-6.0-part1"}''^[[0m
2019-08-30T06:23:30.127 ^[[mNotice: 2019-08-30 06:23:30 +0000 /Stage[main]/Platform::Ceph::Osds/Platform_ceph_osd[stor-22]/Exec[configure journal location stor-22]/returns: Fixing journal location for OSD id: 1^[[0m
2019-08-30T06:23:30.129 ^[[mNotice: 2019-08-30 06:23:30 +0000 /Stage[main]/Platform::Ceph::Osds/Platform_ceph_osd[stor-22]/Exec[configure journal location stor-22]/returns: Symlink created: /var/lib/ceph/osd/ceph-1/journal -> /dev/disk/by-partuuid/4f3e224e-0f97-4a8b-85b8-fa512a8ec042^[[0m
2019-08-30T06:23:30.130 ^[[mNotice: 2019-08-30 06:23:30 +0000 /Stage[main]/Platform::Ceph::Osds/Platform_ceph_osd[stor-22]/Exec[configure journal location stor-22]/returns: Error initializing journal node: /dev/sdb2 for osd id: 1 ceph-osd return code: 250 reason: 2019-08-30 06:23:30.119 7f464315c1c0 -1 open: failed to lock pidfile /var/run/ceph/osd.1.pid because another process locked it.^[[0m

And after puppet apply /var/lib/ceph/osd/ceph-1/journal already link to /dev/sdb2 (journal disk, parttition 2, for this time deploy, /dev/sdb is journal disk, /dev/sdb1 for osd 0)

You can check log I uploaded.

Fix proposed to branch: master
Review: https://review.opendev.org/680897

Change abandoned by chen haochuan (<email address hidden>) on branch: master
Review: https://review.opendev.org/679185

Reviewed: https://review.opendev.org/680897
Committed: https://git.openstack.org/cgit/starlingx/stx-puppet/commit/?id=3a387d729b73c23e584f2430a42b8155b225130f
Submitter: Zuul
Branch: master

commit 3a387d729b73c23e584f2430a42b8155b225130f
Author: Martin, Chen <email address hidden>
Date: Thu Aug 29 20:55:50 2019 +0800

    Fix journal disk path incorrect initialize with dedicate journal disk

    When user provision a storage node with dedicated storage add for
    journal, it is designated to create journal partition on this dedicated
    disk for every osd.
        $ system host-stor-add storage-0 journal <disk uuid>
        $ system host-stor-add storage-0 osd <disk uuid>

    For above case, "ceph-disk prepare" request correct journal partition
    for initialize and write header and keyring to journal disk.

    Closes-Bug: 1830736

    Change-Id: I70ae1a3bc049ad3842e0ec22851b148de5671781
    Signed-off-by: Martin, Chen <email address hidden>

@Martin, when the change has sufficient soak in master and sanity is green, please cherrypick to r/stx.2.0

tested on build 2019-09-22 20:01:30 . Lock and unlock worked on both storage.

@Martin, Given that Jeyan verified the fix in master, please cherry-pick the change to r/stx.2.0 asap.

Fix proposed to branch: r/stx.2.0
Review: https://review.opendev.org/684438

Reviewed: https://review.opendev.org/684438
Committed: https://git.openstack.org/cgit/starlingx/config/commit/?id=3e5e741f47cb4d226e73b0632741af6446e606b7
Submitter: Zuul
Branch: r/stx.2.0

commit 3e5e741f47cb4d226e73b0632741af6446e606b7
Author: Martin, Chen <email address hidden>
Date: Thu Aug 29 20:55:50 2019 +0800

    Fix journal disk path incorrect initialize with dedicate journal disk

    When user provision a storage node with dedicated storage add for
    journal, it is designated to create journal partition on this dedicated
    disk for every osd.
        $ system host-stor-add storage-0 journal <disk uuid>
        $ system host-stor-add storage-0 osd <disk uuid>

    For above case, "ceph-disk prepare" request correct journal partition
    for initialize and write header and keyring to journal disk.

    Closes-Bug: 1830736

    Change-Id: I70ae1a3bc049ad3842e0ec22851b148de5671781
    Signed-off-by: Martin, Chen <email address hidden>