Re: Ceph Luminous - pg is down due to src/osd/SnapMapper.cc: 246: FAILED assert(r == -2)

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



Hi Sage,

did you had any time to look at the logs?

Stefan

Am 05.02.2018 um 14:39 schrieb Stefan Priebe - Profihost AG:
> Hi Sage,
> 
> Am 02.02.2018 um 22:05 schrieb Sage Weil:
>> On Fri, 2 Feb 2018, Stefan Priebe - Profihost AG wrote:
>>> Am 02.02.2018 um 20:28 schrieb Sage Weil:
>>>> On Fri, 2 Feb 2018, Stefan Priebe - Profihost AG wrote:
>>>>> Hi Sage,
>>>>>
>>>>> some days ago i reverted to stock luminous with
>>>>> https://github.com/liewegas/ceph/commit/e6a04446d21689ae131b0b683b4d76c7c30d8e6a
>>>>> +
>>>>> https://github.com/liewegas/ceph/commit/e17493bdffd7b9a349f377e7877fac741221edfa
>>>>> on top. I scrubbed and deep-scrubbed all pgs before and no errors were
>>>>> found.
>>>>>
>>>>> this worked fine until the ceph balancer runned and started remapping
>>>>> some pgs.
>>>>>
>>>>> This again trigged this assert:
>>>>>
>>>>> /build/ceph/src/osd/SnapMapper.cc: In function 'int
>>>>> SnapMapper::get_snaps(const hobject_t&, SnapMapper::object_snaps*)'
>>>>> thread 7f4289bff700 time 2018-02-02 17:46:33.249579
>>>>> /build/ceph/src/osd/SnapMapper.cc: 154: FAILED assert(!out->snaps.empty())
>>>>>
>>>>> Any idea how to fix it?
>>>>
>>>> Cheap workaround is to comment out that assert.  I'm still tryign to sort 
>>>
>>> Yes i did but i feel unconforable with it as the snapmapper value is
>>> still wrong.
>>>
>>>> out how this happened, though.  Not sure if you shared this already, but:
>>>> - bluestore or filestore?
>>>
>>> As i first reported it only filestore. Now also some bluestore OSDs.
>>>
>>>> - no cache tiering, right?  nowhere on the cluster?
>>> Yes and Yes. Never used cache tiering at all.
>>>
>>>> It looks like the SnapMapper entry with an empty snaps vector came in via 
>>>> add_oid() (update_oid() asserts if the new_snaps is empty; add_oid() 
>>>> doesn't have that check).  There are a few place it could come from, 
>>>> including the on_local_recover() call and the update_snap_map() call.  
>>>> That last one is interesting because it pulls the snaps for a new clone 
>>>> out of the pg log entry.. maybe those aren't getting populated properly.
>>>
>>> Is it also possible that they got corrupted in the past and now ceph is
>>> unable to detect it and repair it with a scrub or deep scrub?
>>>
>>>> Can you confirm that all of the OSDs on the cluster are running the
>>>> latest?  (ceph versions).
>>>
>>> Yes they do - i always check this after each update and i rechecked it
>>> again.
>>
>> Ok thanks!
>>
>> I pushed a branch wip-snapmapper-debug to github.com/liewegas/ceph that 
>> has those commits above plus another one that adds debug messages in the 
>> various places that the empty snap vectors might be coming from.
>>
>> This won't help it get past the rebalance issue you hit above, but 
>> hopefully it will trigger when you create a new clone so we can see how 
>> this is happening.
>>
>> If we need to, I think we can ignore the assert (by commenting it out), 
>> but one downside there is that we'll see my warnings pop up when 
>> recovering those objects so we won't be able to tell where they really 
>> came from. Since you were seeing this on new snaps/clones, though, I'm 
>> hoping we won't end up in that situation!
> 
> the biggest part of the logs is now this stuff:
> 2018-02-05 07:56:32.712366 7fb6893ff700  0 log_channel(cluster) log
> [DBG] : 3.740 scrub ok
> 2018-02-05 08:00:16.033843 7fb68a7fe700 -1 osd.0 pg_epoch: 945191
> pg[3.bbf( v 945191'63020848 (945191'63019283,945191'63020848]
> local-lis/les=944620/944621 n=1612 ec=15/15 lis/c 944620/944620 les/c/f
> 944621/944621/937357 944620/944620/944507) [51,54,0] r=2 lpr=944620
> luod=0'0 crt=945191'63020848 lcod 945191'63020847 active] _scan_snaps no
> head for 3:fdd87083:::rbd_data.67b0ee6b8b4567.00000000000103a1:b0d77
> (have MIN)
> 2018-02-05 08:00:42.123804 7fb6833ff700 -1 osd.0 pg_epoch: 945191
> pg[3.bbf( v 945191'63020901 (945191'63019383,945191'63020901]
> local-lis/les=944620/944621 n=1612 ec=15/15 lis/c 944620/944620 les/c/f
> 944621/944621/937357 944620/944620/944507) [51,54,0] r=2 lpr=944620
> luod=0'0 crt=945191'63020901 lcod 945191'63020900 active] _scan_snaps no
> head for 3:fddb41cc:::rbd_data.9772fb6b8b4567.0000000000000380:b0d9f
> (have MIN)
> 2018-02-05 08:03:49.583574 7fb687bfe700 -1 osd.0 pg_epoch: 945191
> pg[3.caa( v 945191'52090546 (945191'52088948,945191'52090546]
> local-lis/les=944694/944695 n=1709 ec=15/15 lis/c 944694/944694 les/c/f
> 944695/944697/937357 944694/944694/944653) [70,0,93] r=1 lpr=944694
> luod=0'0 crt=945191'52090546 lcod 945191'52090545 active] _scan_snaps no
> head for 3:5530360d:::rbd_data.52a6596b8b4567.0000000000000929:b0d55
> (have MIN)
> 2018-02-05 08:03:50.432394 7fb687bfe700 -1 osd.0 pg_epoch: 945191
> pg[3.caa( v 945191'52090549 (945191'52089048,945191'52090549]
> local-lis/les=944694/944695 n=1709 ec=15/15 lis/c 944694/944694 les/c/f
> 944695/944697/937357 944694/944694/944653) [70,0,93] r=1 lpr=944694
> luod=0'0 crt=945191'52090549 lcod 945191'52090548 active] _scan_snaps no
> head for 3:553243fa:::rbd_data.67b0ee6b8b4567.0000000000009956:b0d77
> (have MIN)
> 2018-02-05 08:03:52.523643 7fb687bfe700 -1 osd.0 pg_epoch: 945191
> pg[3.caa( v 945191'52090549 (945191'52089048,945191'52090549]
> local-lis/les=944694/944695 n=1709 ec=15/15 lis/c 944694/944694 les/c/f
> 944695/944697/937357 944694/944694/944653) [70,0,93] r=1 lpr=944694
> luod=0'0 crt=945191'52090549 lcod 945191'52090548 active] _scan_snaps no
> head for 3:5536f170:::rbd_data.c1a3d66b8b4567.000000000000b729:b0dc5
> (have MIN)
> 2018-02-05 08:03:55.471369 7fb687bfe700 -1 osd.0 pg_epoch: 945191
> pg[3.caa( v 945191'52090549 (945191'52089048,945191'52090549]
> local-lis/les=944694/944695 n=1709 ec=15/15 lis/c 944694/944694 les/c/f
> 944695/944697/937357 944694/944694/944653) [70,0,93] r=1 lpr=944694
> luod=0'0 crt=945191'52090549 lcod 945191'52090548 active] _scan_snaps no
> head for 3:553d2114:::rbd_data.154a9e6b8b4567.0000000000001ea1:b0e4e
> (have MIN)
> 2018-02-05 08:08:55.440715 7fb687bfe700 -1 osd.0 pg_epoch: 945191
> pg[3.7aa( v 945191'144763900 (945191'144762311,945191'144763900]
> local-lis/les=944522/944523 n=1761 ec=15/15 lis/c 944522/944522 les/c/f
> 944523/944551/937357 944522/944522/944522) [39,37,0] r=2 lpr=944522
> luod=0'0 crt=945191'144763900 lcod 945191'144763899 active] _scan_snaps
> no head for 3:55e14d0f:::rbd_data.67b0ee6b8b4567.00000000000025f2:b0d77
> (have MIN)
> 2018-02-05 08:09:09.295844 7fb68efff700 -1 osd.0 pg_epoch: 945191
> pg[3.7aa( v 945191'144763970 (945191'144762411,945191'144763970]
> local-lis/les=944522/944523 n=1761 ec=15/15 lis/c 944522/944522 les/c/f
> 944523/944551/937357 944522/944522/944522) [39,37,0] r=2 lpr=944522
> luod=0'0 crt=945191'144763970 lcod 945191'144763969 active] _scan_snaps
> no head for 3:55e2d7a9:::rbd_data.e40a416b8b4567.000000000000576f:b0df3
> (have MIN)
> 2018-02-05 08:09:26.285493 7fb68efff700 -1 osd.0 pg_epoch: 945191
> pg[3.7aa( v 945191'144764043 (945191'144762511,945191'144764043]
> local-lis/les=944522/944523 n=1762 ec=15/15 lis/c 944522/944522 les/c/f
> 944523/944551/937357 944522/944522/944522) [39,37,0] r=2 lpr=944522
> luod=0'0 crt=945191'144764043 lcod 945191'144764042 active] _scan_snaps
> no head for 3:55e4cbad:::rbd_data.163e9c96b8b4567.000000000000202d:b0d42
> (have MIN)
> 2018-02-05 08:10:36.490452 7fb687bfe700 -1 osd.0 pg_epoch: 945191
> pg[3.7aa( v 945191'144764243 (945191'144762711,945191'144764243]
> local-lis/les=944522/944523 n=1762 ec=15/15 lis/c 944522/944522 les/c/f
> 944523/944551/937357 944522/944522/944522) [39,37,0] r=2 lpr=944522
> luod=0'0 crt=945191'144764243 lcod 945191'144764242 active] _scan_snaps
> no head for 3:55ece3c3:::rbd_data.e60f906b8b4567.00000000000000de:b0dd7
> (have MIN)
> 
> Found nothing else in the looks until now. Should i search for more OSDs
> or is this already something we should consider?
> 
> Stefan
> 
>> Thanks!
>> sage
>>
>>
>>
>>  > 
>>> Stefan
>>>
>>>
>>>>>
>>>>> Greets,
>>>>> Stefan
>>>>>
>>>>> Am 22.01.2018 um 20:01 schrieb Sage Weil:
>>>>>> On Mon, 22 Jan 2018, Stefan Priebe - Profihost AG wrote:
>>>>>>> Hi Sage,
>>>>>>>
>>>>>>> thanks! That one fixed it! Now i'm just waiting if the log ever stops
>>>>>>> telling me:
>>>>>>> 2018-01-22 19:48:44.204004 osd.45 [ERR] osd.45 found snap mapper error
>>>>>>> on pg 3.33e oid
>>>>>>> 3:7cc2e79f:::rbd_data.52ab946b8b4567.00000000000043fb:b0d7c snaps in
>>>>>>> mapper: , oi: b0d7c...repaired
>>>>>>>
>>>>>>> Currently it seems it does an endless repair and never ends.
>>>>>>
>>>>>> On many objects or the same object?
>>>>>>
>>>>>> sage
>>>>>>
>>>>>>>
>>>>>>> Greets,
>>>>>>> Stefan
>>>>>>> Am 22.01.2018 um 15:30 schrieb Sage Weil:
>>>>>>>> On Mon, 22 Jan 2018, Stefan Priebe - Profihost AG wrote:
>>>>>>>>> Hi Sage,
>>>>>>>>>
>>>>>>>>> get_snaps returned the error as there are no snaps in the snapmapper. So
>>>>>>>>> it's OK to skip the assert.
>>>>>>>>>
>>>>>>>>> My biggest problem is now that i'm not able to run a scrub on all PGs to
>>>>>>>>> fix all those errors because in around 1-3% the osd seem to deadlock and
>>>>>>>>> needs to get killed to proceed.
>>>>>>>>
>>>>>>>> I believe this will fix it:
>>>>>>>>
>>>>>>>> https://github.com/liewegas/ceph/commit/wip-snapmapper
>>>>>>>>
>>>>>>>> Cherry-pick that and let me know?
>>>>>>>>
>>>>>>>> Thanks!
>>>>>>>> sage
>>>>>>>>
>>>>>>>>
>>>>>>>>>
>>>>>>>>> The log output is always:
>>>>>>>>>     -3> 2018-01-22 14:02:41.725678 7f10025fe700  0 log_channel(cluster)
>>>>>>>>> log [WRN] : slow request 141.951820 seconds old, received at
>>>>>>>>>  2018-01-22 14:00:19.773706: osd_repop(client.142132381.0:1310126 3.a65
>>>>>>>>> e927921/927902 3:a65be829:::rbd_data.4fbc586b8b4567.00000000
>>>>>>>>> 00000157:head v 927921'526559757) currently commit_sent
>>>>>>>>>     -2> 2018-01-22 14:02:41.725679 7f10025fe700  0 log_channel(cluster)
>>>>>>>>> log [WRN] : slow request 141.643853 seconds old, received at
>>>>>>>>>  2018-01-22 14:00:20.081674: osd_repop(client.139148241.0:15454227 3.ff7
>>>>>>>>> e927921/927798 3:eff12952:::rbd_data.2494d06b8b4567.0000000
>>>>>>>>> 00000147d:head v 927921'29105383) currently commit_sent
>>>>>>>>>     -1> 2018-01-22 14:02:41.725684 7f10025fe700  0 log_channel(cluster)
>>>>>>>>> log [WRN] : slow request 141.313220 seconds old, received at
>>>>>>>>>  2018-01-22 14:00:20.412307: osd_repop(client.138984198.0:82792023 3.de6
>>>>>>>>> e927921/927725 3:67b9dc7d:::rbd_data.7750506b8b4567.0000000
>>>>>>>>> 000000aff:head v 927921'164552063) currently commit_sent
>>>>>>>>>      0> 2018-01-22 14:02:42.426910 7f0fc23fe700 -1 *** Caught signal
>>>>>>>>> (Aborted) **
>>>>>>>>>  in thread 7f0fc23fe700 thread_name:tp_osd_tp
>>>>>>>>>
>>>>>>>>>  ceph version 12.2.2-94-g92923ef
>>>>>>>>> (92923ef323d32d8321e86703ce1f9016f19472fb) luminous (stable)
>>>>>>>>>  1: (()+0xa4423c) [0x561d876ab23c]
>>>>>>>>>  2: (()+0xf890) [0x7f100b974890]
>>>>>>>>>  3: (pthread_cond_wait()+0xbf) [0x7f100b97104f]
>>>>>>>>>  4: (ObjectStore::apply_transactions(ObjectStore::Sequencer*,
>>>>>>>>> std::vector<ObjectStore::Transaction, std::allocator<ObjectStore::Tran
>>>>>>>>> saction> >&, Context*)+0x254) [0x561d8746ac54]
>>>>>>>>>  5: (ObjectStore::apply_transaction(ObjectStore::Sequencer*,
>>>>>>>>> ObjectStore::Transaction&&, Context*)+0x5c) [0x561d87199b2c]
>>>>>>>>>  6: (PG::_scan_snaps(ScrubMap&)+0x8f7) [0x561d871ebf77]
>>>>>>>>>  7: (PG::build_scrub_map_chunk(ScrubMap&, hobject_t, hobject_t, bool,
>>>>>>>>> unsigned int, ThreadPool::TPHandle&)+0x22f) [0x561d871ecc4f]
>>>>>>>>>  8: (PG::replica_scrub(boost::intrusive_ptr<OpRequest>,
>>>>>>>>> ThreadPool::TPHandle&)+0x624) [0x561d871ed574]
>>>>>>>>>  9: (PrimaryLogPG::do_request(boost::intrusive_ptr<OpRequest>&,
>>>>>>>>> ThreadPool::TPHandle&)+0x8b6) [0x561d872ac756]
>>>>>>>>>  10: (OSD::dequeue_op(boost::intrusive_ptr<PG>,
>>>>>>>>> boost::intrusive_ptr<OpRequest>, ThreadPool::TPHandle&)+0x3f7)
>>>>>>>>> [0x561d87138bc7]
>>>>>>>>>  11: (PGQueueable::RunVis::operator()(boost::intrusive_ptr<OpRequest>
>>>>>>>>> const&)+0x57) [0x561d873b0db7]
>>>>>>>>>  12: (OSD::ShardedOpWQ::_process(unsigned int,
>>>>>>>>> ceph::heartbeat_handle_d*)+0x108c) [0x561d87167d1c]
>>>>>>>>>  13: (ShardedThreadPool::shardedthreadpool_worker(unsigned int)+0x88d)
>>>>>>>>> [0x561d876f42bd]
>>>>>>>>>  14: (ShardedThreadPool::WorkThreadSharded::entry()+0x10) [0x561d876f6280]
>>>>>>>>>  15: (()+0x8064) [0x7f100b96d064]
>>>>>>>>>  16: (clone()+0x6d) [0x7f100aa6162d]
>>>>>>>>>  NOTE: a copy of the executable, or `objdump -rdS <executable>` is
>>>>>>>>> needed to interpret this.
>>>>>>>>>
>>>>>>>>> --- logging levels ---
>>>>>>>>>    0/ 5 none
>>>>>>>>>    0/ 0 lockdep
>>>>>>>>>    0/ 0 context
>>>>>>>>>    0/ 0 crush
>>>>>>>>>    0/ 0 mds
>>>>>>>>>    0/ 0 mds_balancer
>>>>>>>>>    0/ 0 mds_locker
>>>>>>>>>    0/ 0 mds_log
>>>>>>>>>    0/ 0 mds_log_expire
>>>>>>>>>    0/ 0 mds_migrator
>>>>>>>>>    0/ 0 buffer
>>>>>>>>>    0/ 0 timer
>>>>>>>>>    0/ 0 filer
>>>>>>>>>    0/ 1 striper
>>>>>>>>>    0/ 0 objecter
>>>>>>>>>    0/ 0 rados
>>>>>>>>>    0/ 0 rbd
>>>>>>>>>    0/ 5 rbd_mirror
>>>>>>>>>    0/ 5 rbd_replay
>>>>>>>>>    0/ 0 journaler
>>>>>>>>>    0/ 0 objectcacher
>>>>>>>>>    0/ 0 client
>>>>>>>>>    0/ 0 osd
>>>>>>>>>    0/ 0 optracker
>>>>>>>>>    0/ 0 objclass
>>>>>>>>>    0/ 0 filestore
>>>>>>>>>    0/ 0 journal
>>>>>>>>>    0/ 0 ms
>>>>>>>>>    0/ 0 mon
>>>>>>>>>    0/ 0 monc
>>>>>>>>>    0/ 0 paxos
>>>>>>>>>    0/ 0 tp
>>>>>>>>>    0/ 0 auth
>>>>>>>>>    1/ 5 crypto
>>>>>>>>>    0/ 0 finisher
>>>>>>>>>    1/ 1 reserver
>>>>>>>>>    0/ 0 heartbeatmap
>>>>>>>>>    0/ 0 perfcounter
>>>>>>>>>    0/ 0 rgw
>>>>>>>>>    1/10 civetweb
>>>>>>>>>    1/ 5 javaclient
>>>>>>>>>    0/ 0 asok
>>>>>>>>>    0/ 0 throttle
>>>>>>>>>    0/ 0 refs
>>>>>>>>>    1/ 5 xio
>>>>>>>>>    1/ 5 compressor
>>>>>>>>>    1/ 5 bluestore
>>>>>>>>>    1/ 5 bluefs
>>>>>>>>>    1/ 3 bdev
>>>>>>>>>    1/ 5 kstore
>>>>>>>>>    4/ 5 rocksdb
>>>>>>>>>    4/ 5 leveldb
>>>>>>>>>    4/ 5 memdb
>>>>>>>>>    1/ 5 kinetic
>>>>>>>>>    1/ 5 fuse
>>>>>>>>>    1/ 5 mgr
>>>>>>>>>    1/ 5 mgrc
>>>>>>>>>    1/ 5 dpdk
>>>>>>>>>    1/ 5 eventtrace
>>>>>>>>>   -2/-2 (syslog threshold)
>>>>>>>>>   -1/-1 (stderr threshold)
>>>>>>>>>   max_recent     10000
>>>>>>>>>   max_new         1000
>>>>>>>>>   log_file /var/log/ceph/ceph-osd.59.log
>>>>>>>>> --- end dump of recent events ---
>>>>>>>>>
>>>>>>>>>
>>>>>>>>> Greets,
>>>>>>>>> Stefan
>>>>>>>>>
>>>>>>>>> Am 21.01.2018 um 21:27 schrieb Sage Weil:
>>>>>>>>>> On Fri, 19 Jan 2018, Stefan Priebe - Profihost AG wrote:
>>>>>>>>>>> Hi Sage,
>>>>>>>>>>>
>>>>>>>>>>> thanks for your reply. I'll do this. What i still don't understand is
>>>>>>>>>>> the following and i hope you might have an idea:
>>>>>>>>>>> 1.) All the snaps mentioned here are fresh - i created them today
>>>>>>>>>>> running luminous? How can they be missing in snapmapper again?
>>>>>>>>>>
>>>>>>>>>> I'm not sure.  It might help if you can set debug_osd=1/10 (or 1/20) so 
>>>>>>>>>> that when you hit the crash we have some context as to what is going on.
>>>>>>>>>>
>>>>>>>>>> Did you track down which part of get_snaps() is returning the error?
>>>>>>>>>>
>>>>>>>>>>> 2.) How did this happen? The cluster was jewel and was updated to
>>>>>>>>>>> luminous when all this happened.
>>>>>>>>>>
>>>>>>>>>> Did this start right after the upgrade?
>>>>>>>>>>
>>>>>>>>>> I started a PR that relaxes some of these assertions so that they clean up 
>>>>>>>>>> instead (unless the debug option is enabled, for our regression testing), 
>>>>>>>>>> but I'm still unclear about what the inconsistency is... any loggin you 
>>>>>>>>>> can provide would help!
>>>>>>>>>>
>>>>>>>>>> Thanks-
>>>>>>>>>> sage
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>> Greets,
>>>>>>>>>>> Stefan
>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>> Am 19.01.2018 um 21:19 schrieb Sage Weil:
>>>>>>>>>>>> I'm guessing it is coming from
>>>>>>>>>>>>
>>>>>>>>>>>>   object_snaps out;
>>>>>>>>>>>>   int r = get_snaps(oid, &out);
>>>>>>>>>>>>   if (r < 0)
>>>>>>>>>>>>     return r;
>>>>>>>>>>>>
>>>>>>>>>>>> in SnapMapper::update_snaps().  I would add a debug statement to to 
>>>>>>>>>>>> confirm that, and possibly also add debug lines to the various return 
>>>>>>>>>>>> points in get_snaps() so you can see why get_snaps is returning an error.
>>>>>>>>>>>>
>>>>>>>>>>>> I'm guessing the way to proceed is to warn but ignore the error, but it's 
>>>>>>>>>>>> hard to say without seeing what the inconsistency there is and whether we 
>>>>>>>>>>>> can tolerate it...
>>>>>>>>>>>>
>>>>>>>>>>>> sage
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>> On Fri, 19 Jan 2018, Stefan Priebe - Profihost AG wrote:
>>>>>>>>>>>>
>>>>>>>>>>>>> HI Sage,
>>>>>>>>>>>>>
>>>>>>>>>>>>> any ideas for this one sawing while doing a deep scrub:
>>>>>>>>>>>>>
>>>>>>>>>>>>>     -1> 2018-01-19 21:14:20.474287 7fbcdeffe700 -1 osd.5 pg_epoch:
>>>>>>>>>>>>> 925542 pg[3.306( v 925542'78349255 (925334'78347749,925542'78349255]
>>>>>>>>>>>>> local-lis/les=925503/925504 n=1752 ec=15/15 lis/c 925503/925503 les/c/f
>>>>>>>>>>>>> 925504/925517/0 925503/925503/925503) [75,31,5] r=2 lpr=925503 luod=0'0
>>>>>>>>>>>>> crt=925542'78349255 lcod 925542'78349254 active] _scan_snaps no head for
>>>>>>>>>>>>> 3:60c0267d:::rbd_data.103fdc6b8b4567.0000000000004c8e:b0ce7 (have MIN)
>>>>>>>>>>>>>
>>>>>>>>>>>>>      0> 2018-01-19 21:14:20.477650 7fbcd3bfe700 -1
>>>>>>>>>>>>> /build/ceph/src/osd/PG.cc: In function 'void PG::update_snap_map(const
>>>>>>>>>>>>> std::vector<pg_log_entry_t>&, ObjectStore::Transaction&)' thread
>>>>>>>>>>>>> 7fbcd3bfe700 time 2018-01-19 21:14:20.474752
>>>>>>>>>>>>> /build/ceph/src/osd/PG.cc: 3420: FAILED assert(r == 0)
>>>>>>>>>>>>>
>>>>>>>>>>>>>  ceph version 12.2.2-94-g92923ef
>>>>>>>>>>>>> (92923ef323d32d8321e86703ce1f9016f19472fb) luminous (stable)
>>>>>>>>>>>>>  1: (ceph::__ceph_assert_fail(char const*, char const*, int, char
>>>>>>>>>>>>> const*)+0x102) [0x55c0100d0372]
>>>>>>>>>>>>>  2: (PG::update_snap_map(std::vector<pg_log_entry_t,
>>>>>>>>>>>>> std::allocator<pg_log_entry_t> > const&,
>>>>>>>>>>>>> anObjectStore::Transaction&)+0x3a5) [0x55c00fbcfe35]
>>>>>>>>>>>>>  3: (PG::append_log(std::vector<pg_log_entry_t,
>>>>>>>>>>>>> std::allocator<pg_log_entry_t> > const&, eversion_t, eversion_t,
>>>>>>>>>>>>> ObjectStore::Transaction&, bool)+0x540) [0x55c00fbf5fc0]
>>>>>>>>>>>>>  4: (PrimaryLogPG::log_operation(std::vector<pg_log_entry_t,
>>>>>>>>>>>>> std::allocator<pg_log_entry_t> > const&,
>>>>>>>>>>>>> boost::optional<pg_hit_set_history_t> const&, eversion_t const&,
>>>>>>>>>>>>> eversion_t const&, bool, ObjectStore::Transaction&)+0x64) [0x55c00fceaeb4]
>>>>>>>>>>>>>  5: (ReplicatedBackend::do_repop(boost::intrusive_ptr<OpRequest>)+0xa92)
>>>>>>>>>>>>> [0x55c00fdf6642]
>>>>>>>>>>>>>  6:
>>>>>>>>>>>>> (ReplicatedBackend::_handle_message(boost::intrusive_ptr<OpRequest>)+0x2a4)
>>>>>>>>>>>>> [0x55c00fdfc684]
>>>>>>>>>>>>>  7: (PGBackend::handle_message(boost::intrusive_ptr<OpRequest>)+0x50)
>>>>>>>>>>>>> [0x55c00fd22030]
>>>>>>>>>>>>>  8: (PrimaryLogPG::do_request(boost::intrusive_ptr<OpRequest>&,
>>>>>>>>>>>>> ThreadPool::TPHandle&)+0x77b) [0x55c00fc8e33b]
>>>>>>>>>>>>>  9: (OSD::dequeue_op(boost::intrusive_ptr<PG>,
>>>>>>>>>>>>> boost::intrusive_ptr<OpRequest>, ThreadPool::TPHandle&)+0x3f7)
>>>>>>>>>>>>> [0x55c00fb1abc7]
>>>>>>>>>>>>>  10: (PGQueueable::RunVis::operator()(boost::intrusive_ptr<OpRequest>
>>>>>>>>>>>>> const&)+0x57) [0x55c00fd92ad7]
>>>>>>>>>>>>>  11: (OSD::ShardedOpWQ::_process(unsigned int,
>>>>>>>>>>>>> ceph::heartbeat_handle_d*)+0x108c) [0x55c00fb49d1c]
>>>>>>>>>>>>>  12: (ShardedThreadPool::shardedthreadpool_worker(unsigned int)+0x88d)
>>>>>>>>>>>>> [0x55c0100d5ffd]
>>>>>>>>>>>>>  13: (ShardedThreadPool::WorkThreadSharded::entry()+0x10) [0x55c0100d7fc0]
>>>>>>>>>>>>>  14: (()+0x8064) [0x7fbd284fb064]
>>>>>>>>>>>>>  15: (clone()+0x6d) [0x7fbd275ef62d]
>>>>>>>>>>>>>  NOTE: a copy of the executable, or `objdump -rdS <executable>` is
>>>>>>>>>>>>> needed to interpret this.
>>>>>>>>>>>>>
>>>>>>>>>>>>>
>>>>>>>>>>>>> Stefan
>>>>>>>>>>>>>
>>>>>>>>>>>>> Am 18.01.2018 um 15:24 schrieb Sage Weil:
>>>>>>>>>>>>>> On Thu, 18 Jan 2018, Stefan Priebe - Profihost AG wrote:
>>>>>>>>>>>>>>> Hi Sage,
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> Am 18.01.2018 um 14:16 schrieb Sage Weil:
>>>>>>>>>>>>>>>> On Thu, 18 Jan 2018, Stefan Priebe - Profihost AG wrote:
>>>>>>>>>>>>>>>>> Hi,
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> it also crashes in (marked with HERE):
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> int SnapMapper::get_snaps(
>>>>>>>>>>>>>>>>>   const hobject_t &oid,
>>>>>>>>>>>>>>>>>   object_snaps *out)
>>>>>>>>>>>>>>>>> {
>>>>>>>>>>>>>>>>>   assert(check(oid));
>>>>>>>>>>>>>>>>>   set<string> keys;
>>>>>>>>>>>>>>>>>   map<string, bufferlist> got;
>>>>>>>>>>>>>>>>>   keys.insert(to_object_key(oid));
>>>>>>>>>>>>>>>>>   int r = backend.get_keys(keys, &got);
>>>>>>>>>>>>>>>>>   if (r < 0)
>>>>>>>>>>>>>>>>>     return r;
>>>>>>>>>>>>>>>>>   if (got.empty())
>>>>>>>>>>>>>>>>>     return -ENOENT;
>>>>>>>>>>>>>>>>>   if (out) {
>>>>>>>>>>>>>>>>>     bufferlist::iterator bp = got.begin()->second.begin();
>>>>>>>>>>>>>>>>>     ::decode(*out, bp);
>>>>>>>>>>>>>>>>>     dout(20) << __func__ << " " << oid << " " << out->snaps << dendl;
>>>>>>>>>>>>>>>>>     assert(!out->snaps.empty());            ########### HERE ###########
>>>>>>>>>>>>>>>>>   } else {
>>>>>>>>>>>>>>>>>     dout(20) << __func__ << " " << oid << " (out == NULL)" << dendl;
>>>>>>>>>>>>>>>>>   }
>>>>>>>>>>>>>>>>>   return 0;
>>>>>>>>>>>>>>>>> }
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> is it save to comment that assert?
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> I think so.  All of these asserts are just about ensuring the snapmapper 
>>>>>>>>>>>>>>>> state is consistent, and it's only purpose is to find snaps to trim.  
>>>>>>>>>>>>>>>> Since your snapmapper metadata is clearly not consistent, there isn't a 
>>>>>>>>>>>>>>>> whole lot of risk here.  You might want to set nosnaptrim for the time 
>>>>>>>>>>>>>>>> being so you don't get a surprise if trimming kicks in.  The next step is 
>>>>>>>>>>>>>>>> probably going to be to do a scrub and see what it finds, repairs, or 
>>>>>>>>>>>>>>>> can't repair.
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> snap trimming works fine i already trimmed and removed some snaps.
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> I was able to get the cluster into a state where all is backfilled. But
>>>>>>>>>>>>>>> enabling / doing deep-scrubs results into this one:
>>>>>>>>>>>>>>>      0> 2018-01-18 13:00:54.843076 7fbd253ff700 -1
>>>>>>>>>>>>>>> /build/ceph/src/osd/SnapMapper.cc: In function 'int
>>>>>>>>>>>>>>> SnapMapper::get_snaps(const h
>>>>>>>>>>>>>>> object_t&, SnapMapper::object_snaps*)' thread 7fbd253ff700 time
>>>>>>>>>>>>>>> 2018-01-18 13:00:54.840396
>>>>>>>>>>>>>>> /build/ceph/src/osd/SnapMapper.cc: 154: FAILED assert(!out->snaps.empty())
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> I think if you switch that assert to a warning it will repair...
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> sage
>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>  ceph version 12.2.2-94-g92923ef
>>>>>>>>>>>>>>> (92923ef323d32d8321e86703ce1f9016f19472fb) luminous (stable)
>>>>>>>>>>>>>>>  1: (ceph::__ceph_assert_fail(char const*, char const*, int, char
>>>>>>>>>>>>>>> const*)+0x102) [0x5561ce28d1f2]
>>>>>>>>>>>>>>>  2: (SnapMapper::get_snaps(hobject_t const&,
>>>>>>>>>>>>>>> SnapMapper::object_snaps*)+0x46b) [0x5561cdef755b]
>>>>>>>>>>>>>>>  3: (SnapMapper::get_snaps(hobject_t const&, std::set<snapid_t,
>>>>>>>>>>>>>>> std::less<snapid_t>, std::allocator<snapid_t> >*)+0xd7) [0x5561cdef7
>>>>>>>>>>>>>>> 697]
>>>>>>>>>>>>>>>  4: (PG::_scan_snaps(ScrubMap&)+0x692) [0x5561cdd8ad22]
>>>>>>>>>>>>>>>  5: (PG::build_scrub_map_chunk(ScrubMap&, hobject_t, hobject_t, bool,
>>>>>>>>>>>>>>> unsigned int, ThreadPool::TPHandle&)+0x22f) [0x5561cdd8bc5f]
>>>>>>>>>>>>>>>  6: (PG::replica_scrub(boost::intrusive_ptr<OpRequest>,
>>>>>>>>>>>>>>> ThreadPool::TPHandle&)+0x624) [0x5561cdd8c584]
>>>>>>>>>>>>>>>  7: (PrimaryLogPG::do_request(boost::intrusive_ptr<OpRequest>&,
>>>>>>>>>>>>>>> ThreadPool::TPHandle&)+0x8b6) [0x5561cde4b326]
>>>>>>>>>>>>>>>  8: (OSD::dequeue_op(boost::intrusive_ptr<PG>,
>>>>>>>>>>>>>>> boost::intrusive_ptr<OpRequest>, ThreadPool::TPHandle&)+0x3f7)
>>>>>>>>>>>>>>> [0x5561cdcd7bc7]
>>>>>>>>>>>>>>>  9: (PGQueueable::RunVis::operator()(boost::intrusive_ptr<OpRequest>
>>>>>>>>>>>>>>> const&)+0x57) [0x5561cdf4f957]
>>>>>>>>>>>>>>>  10: (OSD::ShardedOpWQ::_process(unsigned int,
>>>>>>>>>>>>>>> ceph::heartbeat_handle_d*)+0x108c) [0x5561cdd06d1c]
>>>>>>>>>>>>>>>  11: (ShardedThreadPool::shardedthreadpool_worker(unsigned int)+0x88d)
>>>>>>>>>>>>>>> [0x5561ce292e7d]
>>>>>>>>>>>>>>>  12: (ShardedThreadPool::WorkThreadSharded::entry()+0x10) [0x5561ce294e40]
>>>>>>>>>>>>>>>  13: (()+0x8064) [0x7fbd70d86064]
>>>>>>>>>>>>>>>  14: (clone()+0x6d) [0x7fbd6fe7a62d]
>>>>>>>>>>>>>>>  NOTE: a copy of the executable, or `objdump -rdS <executable>` is
>>>>>>>>>>>>>>> needed to interpret this.
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> Greets,
>>>>>>>>>>>>>>> Stefan
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> sage
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> Stefan
>>>>>>>>>>>>>>>>> Am 17.01.2018 um 19:56 schrieb Sage Weil:
>>>>>>>>>>>>>>>>>> On Wed, 17 Jan 2018, Stefan Priebe - Profihost AG wrote:
>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>> Am 17.01.2018 um 19:48 schrieb Sage Weil:
>>>>>>>>>>>>>>>>>>>> On Wed, 17 Jan 2018, Stefan Priebe - Profihost AG wrote:
>>>>>>>>>>>>>>>>>>>>> Hi Sage,
>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>> this gives me another crash while that pg is recovering:
>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>      0> 2018-01-17 19:25:09.328935 7f48f8fff700 -1
>>>>>>>>>>>>>>>>>>>>> /build/ceph/src/osd/PrimaryLogPG.cc: In function 'virtual void
>>>>>>>>>>>>>>>>>>>>> PrimaryLogPG::on_l
>>>>>>>>>>>>>>>>>>>>> ocal_recover(const hobject_t&, const ObjectRecoveryInfo&,
>>>>>>>>>>>>>>>>>>>>> ObjectContextRef, bool, ObjectStore::Transaction*)' thread 7f48f8fff700 ti
>>>>>>>>>>>>>>>>>>>>> me 2018-01-17 19:25:09.322287
>>>>>>>>>>>>>>>>>>>>> /build/ceph/src/osd/PrimaryLogPG.cc: 358: FAILED assert(p !=
>>>>>>>>>>>>>>>>>>>>> recovery_info.ss.clone_snaps.end())
>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>> Is this a cache tiering pool?
>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>> no normal 3 replica but the pg is degraded:
>>>>>>>>>>>>>>>>>>> ceph pg dump | grep 3.80e
>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>> 3.80e      1709                  0     1579         0       0 6183674368
>>>>>>>>>>>>>>>>>>> 10014    10014 active+undersized+degraded+remapped+backfill_wait
>>>>>>>>>>>>>>>>>>> 2018-01-17 19:42:55.840884  918403'70041375  918403:77171331 [50,54,86]
>>>>>>>>>>>>>>>>>>>        50       [39]             39  907737'69776430 2018-01-14
>>>>>>>>>>>>>>>>>>> 22:19:54.110864  907737'69776430 2018-01-14 22:19:54.110864
>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>> Hrm, no real clues on teh root cause then.  Something like this will work 
>>>>>>>>>>>>>>>>>> around the current assert:
>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>> diff --git a/src/osd/PrimaryLogPG.cc b/src/osd/PrimaryLogPG.cc
>>>>>>>>>>>>>>>>>> index d42f3a401b..0f76134f74 100644
>>>>>>>>>>>>>>>>>> --- a/src/osd/PrimaryLogPG.cc
>>>>>>>>>>>>>>>>>> +++ b/src/osd/PrimaryLogPG.cc
>>>>>>>>>>>>>>>>>> @@ -372,8 +372,11 @@ void PrimaryLogPG::on_local_recover(
>>>>>>>>>>>>>>>>>>      set<snapid_t> snaps;
>>>>>>>>>>>>>>>>>>      dout(20) << " snapset " << recovery_info.ss << dendl;
>>>>>>>>>>>>>>>>>>      auto p = recovery_info.ss.clone_snaps.find(hoid.snap);
>>>>>>>>>>>>>>>>>> -    assert(p != recovery_info.ss.clone_snaps.end());  // hmm, should we warn?
>>>>>>>>>>>>>>>>>> -    snaps.insert(p->second.begin(), p->second.end());
>>>>>>>>>>>>>>>>>> +    if (p != recovery_info.ss.clone_snaps.end()) {
>>>>>>>>>>>>>>>>>> +      derr << __func__ << " no clone_snaps for " << hoid << dendl;
>>>>>>>>>>>>>>>>>> +    } else {
>>>>>>>>>>>>>>>>>> +      snaps.insert(p->second.begin(), p->second.end());
>>>>>>>>>>>>>>>>>> +    }
>>>>>>>>>>>>>>>>>>      dout(20) << " snaps " << snaps << dendl;
>>>>>>>>>>>>>>>>>>      snap_mapper.add_oid(
>>>>>>>>>>>>>>>>>>        recovery_info.soid,
>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>> Stefan
>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>> s
>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>  ceph version 12.2.2-94-g92923ef
>>>>>>>>>>>>>>>>>>>>> (92923ef323d32d8321e86703ce1f9016f19472fb) luminous (stable)
>>>>>>>>>>>>>>>>>>>>>  1: (ceph::__ceph_assert_fail(char const*, char const*, int, char
>>>>>>>>>>>>>>>>>>>>> const*)+0x102) [0x55addb5eb1f2]
>>>>>>>>>>>>>>>>>>>>>  2: (PrimaryLogPG::on_local_recover(hobject_t const&, ObjectRecoveryInfo
>>>>>>>>>>>>>>>>>>>>> const&, std::shared_ptr<ObjectContext>, bool,
>>>>>>>>>>>>>>>>>>>>> ObjectStore::Transaction*)+0x11f0) [0x55addb1957a0]
>>>>>>>>>>>>>>>>>>>>>  3: (ReplicatedBackend::handle_push(pg_shard_t, PushOp const&,
>>>>>>>>>>>>>>>>>>>>> PushReplyOp*, ObjectStore::Transaction*)+0x31d) [0x55addb3071ed]
>>>>>>>>>>>>>>>>>>>>>  4: (ReplicatedBackend::_do_push(boost::intrusive_ptr<OpRequest>)+0x18f)
>>>>>>>>>>>>>>>>>>>>> [0x55addb30748f]
>>>>>>>>>>>>>>>>>>>>>  5:
>>>>>>>>>>>>>>>>>>>>> (ReplicatedBackend::_handle_message(boost::intrusive_ptr<OpRequest>)+0x2d1)
>>>>>>>>>>>>>>>>>>>>> [0x55addb317531]
>>>>>>>>>>>>>>>>>>>>>  6: (PGBackend::handle_message(boost::intrusive_ptr<OpRequest>)+0x50)
>>>>>>>>>>>>>>>>>>>>> [0x55addb23cf10]
>>>>>>>>>>>>>>>>>>>>>  7: (PrimaryLogPG::do_request(boost::intrusive_ptr<OpRequest>&,
>>>>>>>>>>>>>>>>>>>>> ThreadPool::TPHandle&)+0x77b) [0x55addb1a91eb]
>>>>>>>>>>>>>>>>>>>>>  8: (OSD::dequeue_op(boost::intrusive_ptr<PG>,
>>>>>>>>>>>>>>>>>>>>> boost::intrusive_ptr<OpRequest>, ThreadPool::TPHandle&)+0x3f7)
>>>>>>>>>>>>>>>>>>>>> [0x55addb035bc7]
>>>>>>>>>>>>>>>>>>>>>  9: (PGQueueable::RunVis::operator()(boost::intrusive_ptr<OpRequest>
>>>>>>>>>>>>>>>>>>>>> const&)+0x57) [0x55addb2ad957]
>>>>>>>>>>>>>>>>>>>>>  10: (OSD::ShardedOpWQ::_process(unsigned int,
>>>>>>>>>>>>>>>>>>>>> ceph::heartbeat_handle_d*)+0x108c) [0x55addb064d1c]
>>>>>>>>>>>>>>>>>>>>>  11: (ShardedThreadPool::shardedthreadpool_worker(unsigned int)+0x88d)
>>>>>>>>>>>>>>>>>>>>> [0x55addb5f0e7d]
>>>>>>>>>>>>>>>>>>>>>  12: (ShardedThreadPool::WorkThreadSharded::entry()+0x10) [0x55addb5f2e40]
>>>>>>>>>>>>>>>>>>>>>  13: (()+0x8064) [0x7f4955b68064]
>>>>>>>>>>>>>>>>>>>>>  14: (clone()+0x6d) [0x7f4954c5c62d]
>>>>>>>>>>>>>>>>>>>>>  NOTE: a copy of the executable, or `objdump -rdS <executable>` is
>>>>>>>>>>>>>>>>>>>>> needed to interpret this.
>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>> Greets,
>>>>>>>>>>>>>>>>>>>>> Stefan
>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>> Am 17.01.2018 um 15:28 schrieb Sage Weil:
>>>>>>>>>>>>>>>>>>>>>> On Wed, 17 Jan 2018, Stefan Priebe - Profihost AG wrote:
>>>>>>>>>>>>>>>>>>>>>>> Hi,
>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>> i there any chance to fix this instead of removing manually all the clones?
>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>> I believe you can avoid the immediate problem and get the PG up by 
>>>>>>>>>>>>>>>>>>>>>> commenting out the assert.  set_snaps() will overwrite the object->snap 
>>>>>>>>>>>>>>>>>>>>>> list mapping.
>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>> The problem is you'll probably still a stray snapid -> object mapping, so 
>>>>>>>>>>>>>>>>>>>>>> when snaptrimming runs you might end up with a PG in the snaptrim_error 
>>>>>>>>>>>>>>>>>>>>>> state that won't trim (although from a quick look at the code it won't 
>>>>>>>>>>>>>>>>>>>>>> crash).  I'd probably remove the assert and deal with that if/when it 
>>>>>>>>>>>>>>>>>>>>>> happens.
>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>> I'm adding a ticket to relax these asserts for production but keep them 
>>>>>>>>>>>>>>>>>>>>>> enabled for qa.  This isn't something that needs to take down the OSD!
>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>> sage
>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>  > 
>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>> Stefan
>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>> Am 16.01.2018 um 23:24 schrieb Gregory Farnum:
>>>>>>>>>>>>>>>>>>>>>>>> On Mon, Jan 15, 2018 at 5:23 PM, Stefan Priebe - Profihost AG
>>>>>>>>>>>>>>>>>>>>>>>> <s.priebe@xxxxxxxxxxxx> wrote:
>>>>>>>>>>>>>>>>>>>>>>>>> Hello,
>>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>>> currently one of my clusters is missing a whole pg due to all 3 osds
>>>>>>>>>>>>>>>>>>>>>>>>> being down.
>>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>>> All of them fail with:
>>>>>>>>>>>>>>>>>>>>>>>>>     0> 2018-01-16 02:05:33.353293 7f944dbfe700 -1
>>>>>>>>>>>>>>>>>>>>>>>>> /build/ceph/src/osd/SnapMapper.cc: In function 'void
>>>>>>>>>>>>>>>>>>>>>>>>> SnapMapper::add_oid(const hobject_t&, const std::set<snapid_t>&,
>>>>>>>>>>>>>>>>>>>>>>>>> MapCacher::Transaction<std::basic_string<char>, ceph::buffer::list>*)'
>>>>>>>>>>>>>>>>>>>>>>>>> thread 7f944dbfe700 time 2018-01-16 02:05:33.349946
>>>>>>>>>>>>>>>>>>>>>>>>> /build/ceph/src/osd/SnapMapper.cc: 246: FAILED assert(r == -2)
>>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>>>  ceph version 12.2.2-93-gd6da8d7
>>>>>>>>>>>>>>>>>>>>>>>>> (d6da8d77a4b2220e6bdd61e4bdd911a9cd91946c) luminous (stable)
>>>>>>>>>>>>>>>>>>>>>>>>>  1: (ceph::__ceph_assert_fail(char const*, char const*, int, char
>>>>>>>>>>>>>>>>>>>>>>>>> const*)+0x102) [0x561f9ff0b1e2]
>>>>>>>>>>>>>>>>>>>>>>>>>  2: (SnapMapper::add_oid(hobject_t const&, std::set<snapid_t,
>>>>>>>>>>>>>>>>>>>>>>>>> std::less<snapid_t>, std::allocator<snapid_t> > const&,
>>>>>>>>>>>>>>>>>>>>>>>>> MapCacher::Transaction<std::string, ceph::buffer::list>*)+0x64b)
>>>>>>>>>>>>>>>>>>>>>>>>> [0x561f9fb76f3b]
>>>>>>>>>>>>>>>>>>>>>>>>>  3: (PG::update_snap_map(std::vector<pg_log_entry_t,
>>>>>>>>>>>>>>>>>>>>>>>>> std::allocator<pg_log_entry_t> > const&,
>>>>>>>>>>>>>>>>>>>>>>>>> ObjectStore::Transaction&)+0x38f) [0x561f9fa0ae3f]
>>>>>>>>>>>>>>>>>>>>>>>>>  4: (PG::append_log(std::vector<pg_log_entry_t,
>>>>>>>>>>>>>>>>>>>>>>>>> std::allocator<pg_log_entry_t> > const&, eversion_t, eversion_t,
>>>>>>>>>>>>>>>>>>>>>>>>> ObjectStore::Transaction&, bool)+0x538) [0x561f9fa31018]
>>>>>>>>>>>>>>>>>>>>>>>>>  5: (PrimaryLogPG::log_operation(std::vector<pg_log_entry_t,
>>>>>>>>>>>>>>>>>>>>>>>>> std::allocator<pg_log_entry_t> > const&,
>>>>>>>>>>>>>>>>>>>>>>>>> boost::optional<pg_hit_set_history_t> const&, eversion_t const&,
>>>>>>>>>>>>>>>>>>>>>>>>> eversion_t const&, bool, ObjectStore::Transaction&)+0x64) [0x561f9fb25d64]
>>>>>>>>>>>>>>>>>>>>>>>>>  6: (ReplicatedBackend::do_repop(boost::intrusive_ptr<OpRequest>)+0xa92)
>>>>>>>>>>>>>>>>>>>>>>>>> [0x561f9fc314b2]
>>>>>>>>>>>>>>>>>>>>>>>>>  7:
>>>>>>>>>>>>>>>>>>>>>>>>> (ReplicatedBackend::_handle_message(boost::intrusive_ptr<OpRequest>)+0x2a4)
>>>>>>>>>>>>>>>>>>>>>>>>> [0x561f9fc374f4]
>>>>>>>>>>>>>>>>>>>>>>>>>  8: (PGBackend::handle_message(boost::intrusive_ptr<OpRequest>)+0x50)
>>>>>>>>>>>>>>>>>>>>>>>>> [0x561f9fb5cf10]
>>>>>>>>>>>>>>>>>>>>>>>>>  9: (PrimaryLogPG::do_request(boost::intrusive_ptr<OpRequest>&,
>>>>>>>>>>>>>>>>>>>>>>>>> ThreadPool::TPHandle&)+0x77b) [0x561f9fac91eb]
>>>>>>>>>>>>>>>>>>>>>>>>>  10: (OSD::dequeue_op(boost::intrusive_ptr<PG>,
>>>>>>>>>>>>>>>>>>>>>>>>> boost::intrusive_ptr<OpRequest>, ThreadPool::TPHandle&)+0x3f7)
>>>>>>>>>>>>>>>>>>>>>>>>> [0x561f9f955bc7]
>>>>>>>>>>>>>>>>>>>>>>>>>  11: (PGQueueable::RunVis::operator()(boost::intrusive_ptr<OpRequest>
>>>>>>>>>>>>>>>>>>>>>>>>> const&)+0x57) [0x561f9fbcd947]
>>>>>>>>>>>>>>>>>>>>>>>>>  12: (OSD::ShardedOpWQ::_process(unsigned int,
>>>>>>>>>>>>>>>>>>>>>>>>> ceph::heartbeat_handle_d*)+0x108c) [0x561f9f984d1c]
>>>>>>>>>>>>>>>>>>>>>>>>>  13: (ShardedThreadPool::shardedthreadpool_worker(unsigned int)+0x88d)
>>>>>>>>>>>>>>>>>>>>>>>>> [0x561f9ff10e6d]
>>>>>>>>>>>>>>>>>>>>>>>>>  14: (ShardedThreadPool::WorkThreadSharded::entry()+0x10) [0x561f9ff12e30]
>>>>>>>>>>>>>>>>>>>>>>>>>  15: (()+0x8064) [0x7f949afcb064]
>>>>>>>>>>>>>>>>>>>>>>>>>  16: (clone()+0x6d) [0x7f949a0bf62d]
>>>>>>>>>>>>>>>>>>>>>>>>>  NOTE: a copy of the executable, or `objdump -rdS <executable>` is
>>>>>>>>>>>>>>>>>>>>>>>>> needed to interpret this.
>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>> By the time it gets there, something else has gone wrong. The OSD is
>>>>>>>>>>>>>>>>>>>>>>>> adding a snapid/object pair to its "SnapMapper", and discovering that
>>>>>>>>>>>>>>>>>>>>>>>> there are already entries (which it thinks there shouldn't be).
>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>> You'll need to post more of a log, along with background, if anybody's
>>>>>>>>>>>>>>>>>>>>>>>> going to diagnose it: is there cache tiering on the cluster? What is
>>>>>>>>>>>>>>>>>>>>>>>> this pool used for? Were there other errors on this PG in the past?
>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>> I also notice a separate email about deleting the data; I don't have
>>>>>>>>>>>>>>>>>>>>>>>> any experience with this but you'd probably have to export the PG
>>>>>>>>>>>>>>>>>>>>>>>> using ceph-objectstore-tool and then find a way to delete the object
>>>>>>>>>>>>>>>>>>>>>>>> out of it. I see options to remove both an object and
>>>>>>>>>>>>>>>>>>>>>>>> "remove-clone-metadata" on a particular ID, but I've not used any of
>>>>>>>>>>>>>>>>>>>>>>>> them myself.
>>>>>>>>>>>>>>>>>>>>>>>> -Greg
>>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>> --
>>>>>>>>>>>>>>>>>>>>>>> To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
>>>>>>>>>>>>>>>>>>>>>>> the body of a message to majordomo@xxxxxxxxxxxxxxx
>>>>>>>>>>>>>>>>>>>>>>> More majordomo info at  http://vger.kernel.org/majordomo-info.html
>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>> --
>>>>>>>>>>>>>>>>>>>>> To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
>>>>>>>>>>>>>>>>>>>>> the body of a message to majordomo@xxxxxxxxxxxxxxx
>>>>>>>>>>>>>>>>>>>>> More majordomo info at  http://vger.kernel.org/majordomo-info.html
>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>> --
>>>>>>>>>>>>>>>>>>> To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
>>>>>>>>>>>>>>>>>>> the body of a message to majordomo@xxxxxxxxxxxxxxx
>>>>>>>>>>>>>>>>>>> More majordomo info at  http://vger.kernel.org/majordomo-info.html
>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> --
>>>>>>>>>>>>>>>>> To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
>>>>>>>>>>>>>>>>> the body of a message to majordomo@xxxxxxxxxxxxxxx
>>>>>>>>>>>>>>>>> More majordomo info at  http://vger.kernel.org/majordomo-info.html
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> --
>>>>>>>>>>>>>>> To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
>>>>>>>>>>>>>>> the body of a message to majordomo@xxxxxxxxxxxxxxx
>>>>>>>>>>>>>>> More majordomo info at  http://vger.kernel.org/majordomo-info.html
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>
>>>>>>>>>>>>> --
>>>>>>>>>>>>> To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
>>>>>>>>>>>>> the body of a message to majordomo@xxxxxxxxxxxxxxx
>>>>>>>>>>>>> More majordomo info at  http://vger.kernel.org/majordomo-info.html
>>>>>>>>>>>>>
>>>>>>>>>>>>>
>>>>>>>>>>> --
>>>>>>>>>>> To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
>>>>>>>>>>> the body of a message to majordomo@xxxxxxxxxxxxxxx
>>>>>>>>>>> More majordomo info at  http://vger.kernel.org/majordomo-info.html
>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>
>>>>>>>>>
>>>>>>>
>>>>>>>
>>>>>
>>>>>
>>>
>>>
--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html



[Index of Archives]     [CEPH Users]     [Ceph Large]     [Information on CEPH]     [Linux BTRFS]     [Linux USB Devel]     [Video for Linux]     [Linux Audio Users]     [Yosemite News]     [Linux Kernel]     [Linux SCSI]
  Powered by Linux