Ceph » bluestore

@William - would you please share OSD startup log with debug-bluefs set to 20?

@Will, would you please share the hex dump of block.db file starting offset 0xede000 length 0x8000.

Latest startup log would be nice to have as well to make sure nothing has changed at bluefs since the startup I have log for. (I have a feeling that Rocksdb might attempt data recovery at some point which modifies BlueFS. Hence want to make sure both dump and startup log are in-sync).

@Will - to make block.db extract just use:

dd if=block.db ibs=1 skip=15589376 count=32768 of=dump.out

So intermediate summary on the issue.
Bluefs log contains a transaction (seq = 3790994) with improperly ordered operations in it.
Operations are
OP_LINK db_wal/76554.log ino 50751
OP_UNLINK db_wal/76544.log
OP_UPDATE ino 50571 ...
...

Highly likely reordering OP_LINK and OP_UPDATE ops will fix the issue.
To do this one should swap extent 0xedf022~0x11 and extent 0xedf05c~0x36 in block.db

OK great! How do we do that? And we have at least 4 other OSDs this happened to; should it be the same or how do we check?

Thank you for your help!

William Law wrote:

OK great! How do we do that? And we have at least 4 other OSDs this happened to; should it be the same or how do we check?

Thank you for your help!

Generally any hex editor allowing insert mode should be sufficient. tweak works for me. Just swap the extents manually using editor...
Suggest to dump a 4K extent at 0xedf000 out of block.db using dd, backup it, edit with tweak and copy back to block.db. Perhaps more elegant way of doing this exists though.

As for other OSDs I suggest to treat this one and check if this is a working approach first. If it works more analysis for other OSDs is required as I'm not 100% certain they fail the same way...

Hi William,
this should be 0xedf022~21 indeed.

But extract-337-modified doesn't look correct in any case.
There are at least the following issues:
1) Byte at offset 0x22 should be 0x8 not 0x28
2) Bytes starting 0x58 (22+36) should be 05 06 00 etc (i.e the same as at offset 0x43+ of the original data)
3) Bytes at offset 0x71 (22+36+19) should be 04 06 00 ... (originally present at offset 0x22+)

So the general idea once more.
Originally there are following chunks (with a chunk per op):
(1) 0x22~21, (2)0x43~19, (3)0x5c~36

Resulting list should look like (if I made the calculations properly):
(3)0x22~36, (2) 0x58~19, (3) 0x71~21

William Law wrote:

Hi Igor -

Thanks again for your kind and patient assistance. I think we got mixed up a little and hope you can help.

Did you mean 0xedf022~0x11 or did you mean 0xedf022~0x21? It looks to us like it should perhaps be 0xedf022~0x21.

We got the following error with either 0xedf022~0x21 or 0xedf022~0x11:
root@nero-ceph-debug:~/sthiell# ceph-objectstore-tool --data-path /var/lib/ceph/osd/ceph-337 --op list-pgs --no-mon-config
/build/ceph-14.2.16/src/os/bluestore/BlueStore.cc: In function 'int BlueStore::_upgrade_super()' thread 7f304f4c09c0 time 2021-01-14 19:23:24.558046
/build/ceph-14.2.16/src/os/bluestore/BlueStore.cc: 10561: FAILED ceph_assert(ondisk_format > 0)
ceph version 14.2.16 (762032d6f509d5e7ee7dc008d80fe9c87086603c) nautilus (stable)
1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x152) [0x7f304554dc82]
2: (ceph::__ceph_assertf_fail(char const*, char const*, int, char const*, char const*, ...)+0) [0x7f304554de5d]
3: (BlueStore::_upgrade_super()+0x4b6) [0x55921ff1cc56]
4: (BlueStore::_mount(bool, bool)+0x592) [0x55921ff72fe2]
5: (main()+0x2f75) [0x55921f9ce415]
6: (__libc_start_main()+0xe7) [0x7f3043ce9bf7]
7: (_start()+0x2a) [0x55921f9fb20a]

• Caught signal (Aborted) *
  in thread 7f304f4c09c0 thread_name:ceph-objectstor
  ceph version 14.2.16 (762032d6f509d5e7ee7dc008d80fe9c87086603c) nautilus (stable)
  1: (()+0x12980) [0x7f3044c12980]
  2: (gsignal()+0xc7) [0x7f3043d06fb7]
  3: (abort()+0x141) [0x7f3043d08921]
  4: (ceph::__ceph_assert_fail(char const, char const*, int, char const*)+0x1a3) [0x7f304554dcd3]
  5: (ceph::__ceph_assertf_fail(char const*, char const*, int, char const*, char const*, ...)+0) [0x7f304554de5d]
  6: (BlueStore::_upgrade_super()+0x4b6) [0x55921ff1cc56]
  7: (BlueStore::_mount(bool, bool)+0x592) [0x55921ff72fe2]
  8: (main()+0x2f75) [0x55921f9ce415]
  9: (__libc_start_main()+0xe7) [0x7f3043ce9bf7]
  10: (_start()+0x2a) [0x55921f9fb20a]
  Aborted (core dumped)

Here are the commands we used to extract and apply:
extract: dd if=/var/lib/ceph/osd/ceph-337/block.db of=extract-337 skip=15593472 ibs=1 obs=1 count=4096
apply: dd if=extract-337-modified of=/var/lib/ceph/osd/ceph-337/block.db seek=15593472 obs=1 ibs=1 count=4096

I've attached those files.

Will

William Law wrote:

Hi Igor – thanks for the clarification. We actually did that but for whatever reason, we uploaded the wrong file, sorry. Please find extract-337-modified-fixed that should be correct this time. We also had to change the 32-bit checksum at the end of the transaction, otherwise we get a bad crc error.

Looks good now.
And yeah, sorry, my bad - forgot about checksum wrapping.

Now, with extract-337-modified-fixed applied, ceph-objectstore-tool --op fsck is still failing with the following error:

7> 2021-01-15 17:13:28.959 7f64626459c0 10 bluefs _read h 0x55d8d26e3020 0x3df000~1000 from file(ino 1 size 0x3df000 mtime 0.000000 allocated 500000 extents [1:0x31300000~100000,1:0xc00000~400000])
-6> 2021-01-15 17:13:28.959 7f64626459c0 20 bluefs _read left 0x21000 len 0x1000
-5> 2021-01-15 17:13:28.959 7f64626459c0 20 bluefs _read got 4096
-4> 2021-01-15 17:13:28.959 7f64626459c0 10 bluefs _replay 0x3df000: txn(seq 3760994 len 0xf6 crc 0x20e83d27)
-3> 2021-01-15 17:13:28.959 7f64626459c0 20 bluefs _replay 0x3df000: op_file_update file(ino 50571 size 0xf6bb6de mtime 2021-01-08 13:46:31.307742 allocated f700000 extents [1:0x400000~100000,1:0x21c00000~f600000])
-2> 2021-01-15 17:13:28.959 7f64626459c0 20 bluefs _replay 0x3df000: op_dir_unlink db.wal/076544.log
-1> 2021-01-15 17:13:28.987 7f64626459c0 -1 /build/ceph-14.2.16/src/os/bluestore/BlueFS.cc: In function 'int BlueFS::_replay(bool, bool)' thread 7f64626459c0 time 2021-01-15 17:13:28.966088
/build/ceph-14.2.16/src/os/bluestore/BlueFS.cc: 1064: FAILED ceph_assert(r != q>second->file_map.end())

Yeah, indeed now it asserts on the next op - removing previously erased db.wal/076544.log. See below for options...

Please note that OP_UPDATE and OP_LINK/OP_UNLINK are not on the same inode (50571 vs 50751 - a bit confusing).

IMO you're wrong here. inode is 50571 for both OP_UPDATE and IP_LINK. Here is the snippet from your original startup log:
-2> 2021-01-11 16:55:38.817 7f0157f26c00 20 bluefs _replay 0x3df000: op_dir_link db.wal/076554.log to 50571

and here is the new one:
> -3> 2021-01-15 17:13:28.959 7f64626459c0 20 bluefs _replay 0x3df000: op_file_update file(ino 50571 size 0xf6bb6de mtime 2021-01-08 13:46:31.307742

We also have looked at this further last night, and we think the unlink cannot succeed maybe because there is an earlier transaction that removes it:

-3690> 2021-01-15 17:13:28.947 7f64626459c0 10 bluefs _read h 0x55d8d26e3020 0x102000~1000 from file(ino 1 size 0x102000 mtime 0.000000 allocated 500000 extents [1:0x31300000~100000,1:0xc00000~400000])
-3689> 2021-01-15 17:13:28.947 7f64626459c0 20 bluefs _read left 0xfe000 len 0x1000
-3688> 2021-01-15 17:13:28.947 7f64626459c0 20 bluefs _read got 4096
-3687> 2021-01-15 17:13:28.947 7f64626459c0 10 bluefs _replay 0x102000: txn(seq 3760261 len 0x10a crc 0xcb08369d)
-3686> 2021-01-15 17:13:28.947 7f64626459c0 20 bluefs _replay 0x102000: op_dir_unlink db/CURRENT
-3685> 2021-01-15 17:13:28.947 7f64626459c0 20 bluefs _replay 0x102000: op_file_remove 50570
-3684> 2021-01-15 17:13:28.947 7f64626459c0 20 bluefs _replay 0x102000: op_dir_link db/CURRENT to 50581
-3683> 2021-01-15 17:13:28.947 7f64626459c0 20 bluefs _replay 0x102000: op_dir_unlink db/076554.dbtmp
-3682> 2021-01-15 17:13:28.947 7f64626459c0 20 bluefs _replay 0x102000: op_file_update file(ino 50582 size 0x0 mtime 2021-01-08 16:58:40.964528 allocated 0 extents [])
-3681> 2021-01-15 17:13:28.947 7f64626459c0 20 bluefs _replay 0x102000: op_dir_link db.wal/076555.log to 50582
-3680> 2021-01-15 17:13:28.947 7f64626459c0 20 bluefs _replay 0x102000: op_dir_unlink db.wal/076552.log
-3679> 2021-01-15 17:13:28.947 7f64626459c0 20 bluefs _replay 0x102000: op_file_remove 50578
-3678> 2021-01-15 17:13:28.947 7f64626459c0 20 bluefs _replay 0x102000: op_dir_unlink db.wal/076544.log <<<
-3677> 2021-01-15 17:13:28.947 7f64626459c0 20 bluefs _replay 0x102000: op_file_remove 50571
-3676> 2021-01-15 17:13:28.947 7f64626459c0 20 bluefs _replay 0x102000: op_dir_unlink db/MANIFEST-076543
-3675> 2021-01-15 17:13:28.947 7f64626459c0 20 bluefs _replay 0x102000: op_file_remove 50569
-3674> 2021-01-15 17:13:28.947 7f64626459c0 20 bluefs _replay 0x102000: op_dir_unlink db/076553.sst
-3673> 2021-01-15 17:13:28.947 7f64626459c0 20 bluefs _replay 0x102000: op_file_remove 50579

Let us know what you think. Thanks again.

Yeah, this analysis is valid. Actually by swapping OP_UPDATE and OP_LINK I'm trying to work this around. But missed that OP_UNLINK would trigger another assertion for the same reason - already removed file.

So I can see two (non-trivial) options to proceed
1) Build custom ceph osd with a patch to avoid assertion on this "invalid" remove op.
2) Rebuild the whole transaction through manual hex editing and wipe out remove op from there. Which might need to rebuilding all the length fields within the transaction which wraps the op list. Not to mention another checksum update.

Igor Fedotov wrote:

Hi William,
this should be 0xedf022~21 indeed.

But extract-337-modified doesn't look correct in any case.
There are at least the following issues:
1) Byte at offset 0x22 should be 0x8 not 0x28
2) Bytes starting 0x58 (22+36) should be 05 06 00 etc (i.e the same as at offset 0x43+ of the original data)
3) Bytes at offset 0x71 (22+36+19) should be 04 06 00 ... (originally present at offset 0x22+)

So the general idea once more.
Originally there are following chunks (with a chunk per op):
(1) 0x22~21, (2)0x43~19, (3)0x5c~36

Resulting list should look like (if I made the calculations properly):
(3)0x22~36, (2) 0x58~19, (3) 0x71~21

Hi Igor -

Thank you for your help and two options; we will discuss.

Given this, is there any way we could (relatively easily) extract PGs from the OSD?

Will

William Law wrote:

Hi Igor -

Thank you for your help and two options; we will discuss.

Given this, is there any way we could (relatively easily) extract PGs from the OSD?

I suppose this would require bluefs log replay anyway hence we are back to the same issue.

Hi @Igor Gajowiak,

It looks like we're experiencing this at the moment. We've moved some pools from hdd only osds to nvme osds and added some extra hdd osds. This results, to no surprise to anyone, in very intense backfills. All pools had already been successfully migrated to the new nvmes before I added the hdds. Now the hdds have started to die after a few hours of intense backfill activity. At the moment there is no indication that any of this is caused by hardware failures and we've now encountered this for 5 OSDs.
I've stopped all I/O on the cluster (pauserd,pausewr,noout,nobackfill,norebalance,norecover,nodeep-scrub). One pg is 'down', from which I could recover. I've started this because but I really can't afford to loose one more OSD.

I'm on a 15.2.2 cluster.

Do we have any idea what the cause of this bug is? The closest thing I could find was this bug report: https://tracker.ceph.com/issues/45613

We are have not tuned the osds at all and we are not using bluefs_buffered_io. Example from ceph daemon:

"bluefs_buffered_io": "false",
"bluefs_preextend_wal_files": "true",

Example log tail:

2021-02-26T03:56:41.442-0500 7fb4ae7d6f00  4 rocksdb: [db/version_set.cc:3766] Column family [default] (ID 0), log number is 76232

2021-02-26T03:56:41.445-0500 7fb4ae7d6f00  4 rocksdb: EVENT_LOG_v1 {"time_micros": 1614329801446019, "job": 1, "event": "recovery_started", "log_files": [76207, 76232]}
2021-02-26T03:56:41.445-0500 7fb4ae7d6f00  4 rocksdb: [db/db_impl_open.cc:583] Recovering log #76207 mode 0
2021-02-26T03:56:43.968-0500 7fb4ae7d6f00  3 rocksdb: [db/db_impl_open.cc:518] db.wal/076207.log: dropping 107997389 bytes; Corruption: error in middle of record
2021-02-26T03:56:43.968-0500 7fb4ae7d6f00  3 rocksdb: [db/db_impl_open.cc:518] db.wal/076207.log: dropping 32757 bytes; Corruption: missing start of fragmented record(1)
2021-02-26T03:56:43.968-0500 7fb4ae7d6f00  3 rocksdb: [db/db_impl_open.cc:518] db.wal/076207.log: dropping 32757 bytes; Corruption: missing start of fragmented record(1)
2021-02-26T03:56:43.968-0500 7fb4ae7d6f00  3 rocksdb: [db/db_impl_open.cc:518] db.wal/076207.log: dropping 32757 bytes; Corruption: missing start of fragmented record(1)
2021-02-26T03:56:43.968-0500 7fb4ae7d6f00  3 rocksdb: [db/db_impl_open.cc:518] db.wal/076207.log: dropping 32757 bytes; Corruption: missing start of fragmented record(1)
2021-02-26T03:56:43.968-0500 7fb4ae7d6f00  3 rocksdb: [db/db_impl_open.cc:518] db.wal/076207.log: dropping 32757 bytes; Corruption: missing start of fragmented record(1)
2021-02-26T03:56:43.968-0500 7fb4ae7d6f00  3 rocksdb: [db/db_impl_open.cc:518] db.wal/076207.log: dropping 32757 bytes; Corruption: missing start of fragmented record(1)
2021-02-26T03:56:43.968-0500 7fb4ae7d6f00  3 rocksdb: [db/db_impl_open.cc:518] db.wal/076207.log: dropping 32757 bytes; Corruption: missing start of fragmented record(1)
2021-02-26T03:56:43.968-0500 7fb4ae7d6f00  3 rocksdb: [db/db_impl_open.cc:518] db.wal/076207.log: dropping 32757 bytes; Corruption: missing start of fragmented record(1)
~~~~~
2021-02-26T03:56:45.020-0500 7fb4ae7d6f00  3 rocksdb: [db/db_impl_open.cc:518] db.wal/076207.log: dropping 32757 bytes; Corruption: missing start of fragmented record(1)                                          
2021-02-26T03:56:45.020-0500 7fb4ae7d6f00  3 rocksdb: [db/db_impl_open.cc:518] db.wal/076207.log: dropping 32757 bytes; Corruption: missing start of fragmented record(1)                                          
2021-02-26T03:56:45.020-0500 7fb4ae7d6f00  3 rocksdb: [db/db_impl_open.cc:518] db.wal/076207.log: dropping 32757 bytes; Corruption: missing start of fragmented record(1)                                          
2021-02-26T03:56:45.020-0500 7fb4ae7d6f00  3 rocksdb: [db/db_impl_open.cc:518] db.wal/076207.log: dropping 32757 bytes; Corruption: missing start of fragmented record(1)                                          
2021-02-26T03:56:45.020-0500 7fb4ae7d6f00  3 rocksdb: [db/db_impl_open.cc:518] db.wal/076207.log: dropping 32757 bytes; Corruption: missing start of fragmented record(1)                                          
2021-02-26T03:56:45.020-0500 7fb4ae7d6f00  3 rocksdb: [db/db_impl_open.cc:518] db.wal/076207.log: dropping 32757 bytes; Corruption: missing start of fragmented record(1)                                          
2021-02-26T03:56:45.020-0500 7fb4ae7d6f00  3 rocksdb: [db/db_impl_open.cc:518] db.wal/076207.log: dropping 32757 bytes; Corruption: missing start of fragmented record(1)                                          
2021-02-26T03:56:45.020-0500 7fb4ae7d6f00  3 rocksdb: [db/db_impl_open.cc:518] db.wal/076207.log: dropping 29531 bytes; Corruption: missing start of fragmented record(2)                                          
2021-02-26T03:56:45.020-0500 7fb4ae7d6f00  4 rocksdb: [db/db_impl.cc:390] Shutdown: canceling all background work                                                                                                  
2021-02-26T03:56:45.031-0500 7fb4ae7d6f00  4 rocksdb: [db/db_impl.cc:563] Shutdown complete
2021-02-26T03:56:45.031-0500 7fb4ae7d6f00 -1 rocksdb: Corruption: error in middle of record
2021-02-26T03:56:45.031-0500 7fb4ae7d6f00 -1 bluestore(/var/lib/ceph/osd/ceph-49) _open_db erroring opening db:                                                                                                    
2021-02-26T03:56:45.031-0500 7fb4ae7d6f00  1 bluefs umount
2021-02-26T03:56:45.031-0500 7fb4ae7d6f00  1 fbmap_alloc 0x55aaac2a2800 shutdown
2021-02-26T03:56:45.032-0500 7fb4ae7d6f00  1 bdev(0x55aaacf8c700 /var/lib/ceph/osd/ceph-49/block) close
2021-02-26T03:56:45.050-0500 7fb4ae7d6f00  1 bdev(0x55aaacf8c000 /var/lib/ceph/osd/ceph-49/block) close
2021-02-26T03:56:45.298-0500 7fb4ae7d6f00 -1 osd.49 0 OSD:init: unable to mount object store
2021-02-26T03:56:45.298-0500 7fb4ae7d6f00 -1 ESC[0;31m ** ERROR: osd init failed: (5) Input/output errorESC[0m

Hi Wout,

I think https://tracker.ceph.com/issues/45613 is relevant indeed.
Suggest to set bluefs_preextend_wal_files to false ASAP.

Thanks for the reply @Igor Gajowiak.

Can we link the tickets with a "caused by" to https://tracker.ceph.com/issues/45613 ?

In the customer case running luminous when OSD process was run twice (let's skip how), the assert
'file->fnode.ino'
from
BlueFS::_replay(...)
Was ~ 1/10 reasons of OSD fatal failures.