Hi Brad, Indeed - osd.694 kept crashing with a read error (medium error on the hard drive), and got restarted by systemd. So net net the system ended up in an infinite loop of deep scrub attempts on the PG for a week. Typically when a scrub encounters a read error, I get an inconsistent placement group, not an OSD crash and an infinite loop of scrub attempts. With the inconsistent placement group a pg repair fixes the read error (by reallocating the sector inside the drive). Here is the stack trace of the osd.694 crash on the scrub read error: Apr 19 03:39:17 popeye-oss-3-03 kernel: sd 14:0:27:0: [sdz] tag#1 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE Apr 19 03:39:17 popeye-oss-3-03 kernel: sd 14:0:27:0: [sdz] tag#1 Sense Key : Medium Error [current] [descriptor] Apr 19 03:39:17 popeye-oss-3-03 kernel: sd 14:0:27:0: [sdz] tag#1 Add. Sense: Unrecovered read error Apr 19 03:39:17 popeye-oss-3-03 kernel: sd 14:0:27:0: [sdz] tag#1 CDB: Read(10) 28 00 6e a9 7a 30 00 00 80 00 Apr 19 03:39:17 popeye-oss-3-03 kernel: print_req_error: critical medium error, dev sdz, sector 14852804992 Apr 19 03:39:17 popeye-oss-3-03 ceph-osd: 2020-04-19 03:39:17.095 7fffd2e2b700 -1 bluestore(/var/lib/ceph/osd/ceph-694) _do_read bdev-read failed: (61) No data available Apr 19 03:39:17 popeye-oss-3-03 ceph-osd: /home/jenkins-build/build/workspace/ceph-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos7/DIST/centos7/MACHINE_SIZE/huge/release/14.2.8/rpm/el7/BUILD/ceph-14.2.8/src/os/bluestore/BlueStore.cc: In function 'int BlueStore::_do_read(BlueStore::Collection*, BlueStore::OnodeRef, uint64_t, size_t, ceph::bufferlist&, uint32_t, uint64_t)' thread 7fffd2e2b700 time 2020-04-19 03:39:17.099677 Apr 19 03:39:17 popeye-oss-3-03 ceph-osd: /home/jenkins-build/build/workspace/ceph-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos7/DIST/centos7/MACHINE_SIZE/huge/release/14.2.8/rpm/el7/BUILD/ceph-14.2.8/src/os/bluestore/BlueStore.cc: 9214: FAILED ceph_assert(r == 0) Apr 19 03:39:17 popeye-oss-3-03 ceph-osd: ceph version 14.2.8 (2d095e947a02261ce61424021bb43bd3022d35cb) nautilus (stable) Apr 19 03:39:17 popeye-oss-3-03 ceph-osd: 1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x14a) [0x555555a1ea4d] Apr 19 03:39:17 popeye-oss-3-03 ceph-osd: 2: (()+0x4cac15) [0x555555a1ec15] Apr 19 03:39:17 popeye-oss-3-03 ceph-osd: 3: (BlueStore::_do_read(BlueStore::Collection*, boost::intrusive_ptr<BlueStore::Onode>, unsigned long, unsigned long, ceph::buffer::v14_2_0::list&, unsigned int, unsigned long)+0x3512) [0x555555f64132] Apr 19 03:39:17 popeye-oss-3-03 ceph-osd: 4: (BlueStore::read(boost::intrusive_ptr<ObjectStore::CollectionImpl>&, ghobject_t const&, unsigned long, unsigned long, ceph::buffer::v14_2_0::list&, unsigned int)+0x1b8) [0x555555f64778] Apr 19 03:39:17 popeye-oss-3-03 ceph-osd: 5: (ReplicatedBackend::be_deep_scrub(hobject_t const&, ScrubMap&, ScrubMapBuilder&, ScrubMap::object&)+0x2c2) [0x555555deb832] Apr 19 03:39:17 popeye-oss-3-03 ceph-osd: 6: (PGBackend::be_scan_list(ScrubMap&, ScrubMapBuilder&)+0x663) [0x555555d082c3] Apr 19 03:39:17 popeye-oss-3-03 ceph-osd: 7: (PG::build_scrub_map_chunk(ScrubMap&, ScrubMapBuilder&, hobject_t, hobject_t, bool, ThreadPool::TPHandle&)+0x8b) [0x555555bbaacb] Apr 19 03:39:17 popeye-oss-3-03 ceph-osd: 8: (PG::chunky_scrub(ThreadPool::TPHandle&)+0x181c) [0x555555be4fcc] Apr 19 03:39:17 popeye-oss-3-03 ceph-osd: 9: (PG::scrub(unsigned int, ThreadPool::TPHandle&)+0x4bb) [0x555555be61db] Apr 19 03:39:17 popeye-oss-3-03 ceph-osd: 10: (PGScrub::run(OSD*, OSDShard*, boost::intrusive_ptr<PG>&, ThreadPool::TPHandle&)+0x12) [0x555555d8c7b2] Apr 19 03:39:17 popeye-oss-3-03 ceph-osd: 11: (OSD::ShardedOpWQ::_process(unsigned int, ceph::heartbeat_handle_d*)+0x90f) [0x555555b1898f] Apr 19 03:39:17 popeye-oss-3-03 ceph-osd: 12: (ShardedThreadPool::shardedthreadpool_worker(unsigned int)+0x5b6) [0x5555560bd056] Apr 19 03:39:17 popeye-oss-3-03 ceph-osd: 13: (ShardedThreadPool::WorkThreadSharded::entry()+0x10) [0x5555560bfb70] Apr 19 03:39:17 popeye-oss-3-03 ceph-osd: 14: (()+0x7e65) [0x7ffff5025e65] Apr 19 03:39:17 popeye-oss-3-03 ceph-osd: 15: (clone()+0x6d) [0x7ffff3ee988d] I ended up recreating the OSD (and thus overwriting all data) to fix the issue. Andras On 4/20/20 9:28 PM, Brad Hubbard wrote:
On Mon, Apr 20, 2020 at 11:01 PM Andras Pataki <apataki@flatironinstitute.org> wrote:
On a cluster running Nautilus (14.2.8), we are getting a complaint about a PG not being deep-scrubbed on time. Looking at the primary OSD's logs, it looks like it tries to deep-scrub the PG every hour or so, emits some complaints that I don't understand, but the deep scrub does not finish (either with or without a scrub error).
Here is the PG from pg dump:
1.43f 31794 0 0 0 0 66930087214 0 0 3004 3004 active+clean+scrubbing+deep 2020-04-20 04:48:13.055481 46286'483734 46286:563439 [354,694,851] 354 [354,694,851] 354 39594'348643 2020-04-10 12:39:16.261088 38482'314644 2020-04-04 10:37:03.121638 0
Here is a section of the primary OSD logs (osd.354):
2020-04-18 08:21:08.322 7fffd2e2b700 0 log_channel(cluster) log [DBG] : 1.43f deep-scrub starts Scrubbing starts.
2020-04-18 08:37:53.362 7fffd2e2b700 1 osd.354 pg_epoch: 45910 pg[1.43f( v 45909'449615 (45801'446525,45909'449615] local-lis/les=45908/45909 n=30862 ec=874/871 lis/c 45908/45908 les/c/f 45909/45909/0 45910/45910/42988) [354,851] r=0 lpr=45910 pi=[45908,45910)/1 luod=0'0 crt=45909'449615 lcod 45909'449614 mlcod 0'0 active+scrubbing+deep mbc={}] start_peering_interval up [354,694,851] -> [354,851], acting [354,694,851] -> [354,851], acting_primary 354 -> 354, up_primary 354 -> 354, role 0 -> 0, features acting 4611087854031667199 upacting 4611087854031667199 2020-04-18 08:37:53.362 7fffd2e2b700 1 osd.354 pg_epoch: 45910 pg[1.43f( v 45909'449615 (45801'446525,45909'449615] local-lis/les=45908/45909 n=30862 ec=874/871 lis/c 45908/45908 les/c/f 45909/45909/0 45910/45910/42988) [354,851] r=0 lpr=45910 pi=[45908,45910)/1 crt=45909'449615 lcod 45909'449614 mlcod 0'0 unknown mbc={}] state<Start>: transitioning to Primary 2020-04-18 08:38:01.002 7fffd2e2b700 1 osd.354 pg_epoch: 45912 pg[1.43f( v 45909'449615 (45801'446525,45909'449615] local-lis/les=45910/45911 n=30862 ec=874/871 lis/c 45910/45908 les/c/f 45911/45909/0 45912/45912/42988) [354,694,851] r=0 lpr=45912 pi=[45908,45912)/1 luod=0'0 crt=45909'449615 lcod 45909'449614 mlcod 0'0 active mbc={}] start_peering_interval up [354,851] -> [354,694,851], acting [354,851] -> [354,694,851], acting_primary 354 -> 354, up_primary 354 -> 354, role 0 -> 0, features acting 4611087854031667199 upacting 4611087854031667199 Epoch (and therefore map) change from 45910 to 45912 You lost osd 694 from the acting set so peering has to restart and the scrub is aborted.
2020-04-18 08:38:01.002 7fffd2e2b700 1 osd.354 pg_epoch: 45912 pg[1.43f( v 45909'449615 (45801'446525,45909'449615] local-lis/les=45910/45911 n=30862 ec=874/871 lis/c 45910/45908 les/c/f 45911/45909/0 45912/45912/42988) [354,694,851] r=0 lpr=45912 pi=[45908,45912)/1 crt=45909'449615 lcod 45909'449614 mlcod 0'0 unknown mbc={}] state<Start>: transitioning to Primary 2020-04-18 08:40:04.219 7fffd2e2b700 0 log_channel(cluster) log [DBG] : 1.43f deep-scrub starts Scrubbing start again.
2020-04-18 08:56:49.095 7fffd2e2b700 1 osd.354 pg_epoch: 45914 pg[1.43f( v 45913'449735 (45812'446725,45913'449735] local-lis/les=45912/45913 n=30868 ec=874/871 lis/c 45912/45912 les/c/f 45913/45913/0 45914/45914/42988) [354,851] r=0 lpr=45914 pi=[45912,45914)/1 luod=0'0 crt=45913'449735 lcod 45913'449734 mlcod 0'0 active+scrubbing+deep mbc={}] start_peering_interval up [354,694,851] -> [354,851], acting [354,694,851] -> [354,851], acting_primary 354 -> 354, up_primary 354 -> 354, role 0 -> 0, features acting 4611087854031667199 upacting 4611087854031667199 2020-04-18 08:56:49.095 7fffd2e2b700 1 osd.354 pg_epoch: 45914 pg[1.43f( v 45913'449735 (45812'446725,45913'449735] local-lis/les=45912/45913 n=30868 ec=874/871 lis/c 45912/45912 les/c/f 45913/45913/0 45914/45914/42988) [354,851] r=0 lpr=45914 pi=[45912,45914)/1 crt=45913'449735 lcod 45913'449734 mlcod 0'0 unknown mbc={}] state<Start>: transitioning to Primary 2020-04-18 08:56:55.627 7fffd2e2b700 1 osd.354 pg_epoch: 45916 pg[1.43f( v 45913'449735 (45812'446725,45913'449735] local-lis/les=45914/45915 n=30868 ec=874/871 lis/c 45914/45912 les/c/f 45915/45913/0 45916/45916/42988) [354,694,851] r=0 lpr=45916 pi=[45912,45916)/1 luod=0'0 crt=45913'449735 lcod 45913'449734 mlcod 0'0 active mbc={}] start_peering_interval up [354,851] -> [354,694,851], acting [354,851] -> [354,694,851], acting_primary 354 -> 354, up_primary 354 -> 354, role 0 -> 0, features acting 4611087854031667199 upacting 4611087854031667199 Same again, you lost osd 694 from the acting set, epoch and map change requiring repeering and aborting the scrub.
You need to identify why osd 694 is flapping, or at least appears to be flapping to the monitor.
Start by having a careful look at the logs for osd 694. If they provide no insight look at the logs on the active monitor for any reference to osd 694 around the time the epoch changes.
2020-04-18 08:56:55.627 7fffd2e2b700 1 osd.354 pg_epoch: 45916 pg[1.43f( v 45913'449735 (45812'446725,45913'449735] local-lis/les=45914/45915 n=30868 ec=874/871 lis/c 45914/45912 les/c/f 45915/45913/0 45916/45916/42988) [354,694,851] r=0 lpr=45916 pi=[45912,45916)/1 crt=45913'449735 lcod 45913'449734 mlcod 0'0 unknown mbc={}] state<Start>: transitioning to Primary 2020-04-18 08:56:56.867 7fffd2e2b700 0 log_channel(cluster) log [DBG] : 1.43f deep-scrub starts 2020-04-18 09:13:37.419 7fffd2e2b700 1 osd.354 pg_epoch: 45918 pg[1.43f( v 45917'449808 (45812'446725,45917'449808] local-lis/les=45916/45917 n=30876 ec=874/871 lis/c 45916/45916 les/c/f 45917/45917/0 45918/45918/42988) [354,851] r=0 lpr=45918 pi=[45916,45918)/1 luod=0'0 crt=45917'449808 lcod 45917'449807 mlcod 0'0 active+scrubbing+deep mbc={}] start_peering_interval up [354,694,851] -> [354,851], acting [354,694,851] -> [354,851], acting_primary 354 -> 354, up_primary 354 -> 354, role 0 -> 0, features acting 4611087854031667199 upacting 4611087854031667199 2020-04-18 09:13:37.419 7fffd2e2b700 1 osd.354 pg_epoch: 45918 pg[1.43f( v 45917'449808 (45812'446725,45917'449808] local-lis/les=45916/45917 n=30876 ec=874/871 lis/c 45916/45916 les/c/f 45917/45917/0 45918/45918/42988) [354,851] r=0 lpr=45918 pi=[45916,45918)/1 crt=45917'449808 lcod 45917'449807 mlcod 0'0 unknown mbc={}] state<Start>: transitioning to Primary 2020-04-18 09:13:44.959 7fffd2e2b700 1 osd.354 pg_epoch: 45920 pg[1.43f( v 45917'449808 (45812'446725,45917'449808] local-lis/les=45918/45919 n=30876 ec=874/871 lis/c 45918/45916 les/c/f 45919/45917/0 45920/45920/42988) [354,694,851] r=0 lpr=45920 pi=[45916,45920)/1 luod=0'0 crt=45917'449808 lcod 45917'449807 mlcod 0'0 active mbc={}] start_peering_interval up [354,851] -> [354,694,851], acting [354,851] -> [354,694,851], acting_primary 354 -> 354, up_primary 354 -> 354, role 0 -> 0, features acting 4611087854031667199 upacting 4611087854031667199 2020-04-18 09:13:44.959 7fffd2e2b700 1 osd.354 pg_epoch: 45920 pg[1.43f( v 45917'449808 (45812'446725,45917'449808] local-lis/les=45918/45919 n=30876 ec=874/871 lis/c 45918/45916 les/c/f 45919/45917/0 45920/45920/42988) [354,694,851] r=0 lpr=45920 pi=[45916,45920)/1 crt=45917'449808 lcod 45917'449807 mlcod 0'0 unknown mbc={}] state<Start>: transitioning to Primary
I've tried restarting all 3 OSDs in question, it didn't help. I'm running the upmap balancer on this cluster (if that matters). Any ideas?
Andras _______________________________________________ ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io