22 Feb
2020
22 Feb
'20
1:12 a.m.
If it helps at all, I've posted a log with a recent backtrace
ceph-post-file: 589aa7aa-7a80-49a2-ba55-376e467c4550
In fact, the log seems to span two different lifetimes of the same OSD,
the first of which aborted, then rather than repairing, the OSD was
recreated and 12 hours later aborted again.
The most recent sudden abort (before every restart resulted in immediate
crashing). I don't know if this is useful without context. I'll update
the tracker as well with the ceph-post-file.
421/265138) [35,249,486]/[249,24] r=-1 lpr=265421 pi=[265069,265421)/1
luod=0'0 crt=253132'490078 lcod 0'0 active+remapped mbc={}]
start_peering_interval up [35,249] -> [35,249,486], acting [249,24] ->
[249,24], acting_primary 249 -> 249,
up_primary 35 -> 35, role -1 -> -1, features acting
4611087854031667195 upacting 4611087854031667195
2020-02-20 21:07:45.943 7f572e31f700 1 osd.35 pg_epoch: 265421
pg[26.7a( v 253132'490078 (172352'487078,253132'490078] lb MIN (bitwise)
local-lis/les=265138/265139 n=0 ec=24133/13954 lis/c 265373/265069
les/c/f 265374/265070/0 265421/265
421/265138) [35,249,486]/[249,24] r=-1 lpr=265421 pi=[265069,265421)/1
crt=253132'490078 lcod 0'0 remapped NOTIFY mbc={}] state<Start>:
transitioning to Stray
2020-02-20 21:07:46.328 7f5740b44700 4 rocksdb:
[/home/jenkins-build/build/workspace/ceph-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos7/DIST/centos7/MACHINE_SIZE/huge/release/13.2.8/rpm/el7/BUILD/ceph-13.2.8/src/rocksdb/
db/compaction_job.cc:1166] [default] [JOB 3073] Generated table #9747:
177780 keys, 68462819 bytes
2020-02-20 21:07:46.328 7f5740b44700 4 rocksdb: EVENT_LOG_v1
{"time_micros": 1582232866330355, "cf_name": "default",
"job": 3073,
"event": "table_file_creation", "file_number": 9747,
"file_size":
68462819, "table_properties": {"data_size
": 67112690, "index_size": 755444, "filter_size": 593634,
"raw_key_size": 17705409, "raw_average_key_size": 99,
"raw_value_size":
51990011, "raw_average_value_size": 292, "num_data_blocks": 17287,
"num_entries": 177780, "filter_policy_nam
e": "rocksdb.BuiltinBloomFilter", "kDeletedKeys": "0",
"kMergeOperands":
"0"}}
2020-02-20 21:07:46.754 7f5740b44700 4 rocksdb:
[/home/jenkins-build/build/workspace/ceph-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos7/DIST/centos7/MACHINE_SIZE/huge/release/13.2.8/rpm/el7/BUILD/ceph-13.2.8/src/rocksdb/
db/compaction_job.cc:1166] [default] [JOB 3073] Generated table #9748:
177726 keys, 68453977 bytes
2020-02-20 21:07:46.754 7f5740b44700 4 rocksdb: EVENT_LOG_v1
{"time_micros": 1582232866756343, "cf_name": "default",
"job": 3073,
"event": "table_file_creation", "file_number": 9748,
"file_size":
68453977, "table_properties": {"data_size
": 67112764, "index_size": 746762, "filter_size": 593400,
"raw_key_size": 17666827, "raw_average_key_size": 99,
"raw_value_size":
51937731, "raw_average_value_size": 292, "num_data_blocks": 17285,
"num_entries": 177726, "filter_policy_nam
e": "rocksdb.BuiltinBloomFilter", "kDeletedKeys": "0",
"kMergeOperands":
"0"}}
2020-02-20 21:07:47.091 7f573b493700 -1 *** Caught signal (Aborted) **
in thread 7f573b493700 thread_name:ms_dispatch
ceph version 13.2.8 (5579a94fafbc1f9cc913a0f5d362953a5d9c3ae0) mimic
(stable)
1: (()+0xf5f0) [0x7f574d8b85f0]
2: (gsignal()+0x37) [0x7f574c8d8337]
3: (abort()+0x148) [0x7f574c8d9a28]
4: (__gnu_cxx::__verbose_terminate_handler()+0x165) [0x7f574d1e87d5]
5: (()+0x5e746) [0x7f574d1e6746]
6: (()+0x5e773) [0x7f574d1e6773]
7: (()+0x5e993) [0x7f574d1e6993]
8: (OSDMap::decode(ceph::buffer::list::iterator&)+0x160e) [0x7f5750b0b68e]
9: (OSDMap::decode(ceph::buffer::list&)+0x31) [0x7f5750b0ce31]
10: (OSD::handle_osd_map(MOSDMap*)+0x1c2d) [0x55d76e60a2dd]
11: (OSD::_dispatch(Message*)+0xa1) [0x55d76e6143f1]
12: (OSD::ms_dispatch(Message*)+0x56) [0x55d76e614746]
13: (DispatchQueue::entry()+0xb7a) [0x7f5750a0524a]
14: (DispatchQueue::DispatchThread::entry()+0xd) [0x7f5750aa34bd]
15: (()+0x7e65) [0x7f574d8b0e65]
16: (clone()+0x6d) [0x7f574c9a088d]
NOTE: a copy of the executable, or `objdump -rdS <executable>` is
needed to interpret this.
On 2/20/20 7:00 PM, Troy Ablan wrote:
> Dan,
>
> This has happened to HDDs also, and nvme most recently. CentOS 7.7,
> usually the kernel is within 6 months of current updates. We try to
> stay relatively up to date.
>
> -Troy
>
> On 2/20/20 5:28 PM, Dan van der Ster wrote:
>> Another thing... in your thread that you said that only the *SSDs* in
>> your cluster had crashed, but not the HDDs.
>> Both SSDs and HDDs were bluestore? Did the hdds ever crash subsequently?
>> Which OS/kernel do you run? We're CentOS 7 with quite some uptime.
>>
>>
>> On Thu, Feb 20, 2020 at 10:29 PM Troy Ablan <tablan(a)gmail.com> wrote:
>>>
>>> I hope I don't sound too happy to hear that you've run into this
same
>>> problem, but still I'm glad to see that it's not just a one-off
problem
>>> with us. :)
>>>
>>> We're still running Mimic. I haven't yet deployed Nautilus
anywhere.
>>>
>>> Thanks
>>> -Troy
>>>
>>> On 2/20/20 2:14 PM, Dan van der Ster wrote:
>>>> Thanks Troy for the quick response.
>>>> Are you still running mimic on that cluster? Seeing the crashes in
>>>> nautilus too?
>>>>
>>>> Our cluster is also quite old -- so it could very well be memory or
>>>> network gremlins.
>>>>
>>>> Cheers, Dan
>>>>
>>>> On Thu, Feb 20, 2020 at 10:11 PM Troy Ablan <tablan(a)gmail.com>
wrote:
>>>>>
>>>>> Dan,
>>>>>
>>>>> Yes, I have had this happen several times since, but fortunately the
>>>>> last couple of times has only happened to one or two OSDs at a
>>>>> time so
>>>>> it didn't take down entire pools. Remedy has been the same.
>>>>>
>>>>> I had been holding off on too much further investigation because I
>>>>> thought the source of the issue may have been some old hardware
>>>>> gremlins, and we're waiting on some new hardware.
>>>>>
>>>>> -Troy
>>>>>
>>>>>
>>>>> On 2/20/20 1:40 PM, Dan van der Ster wrote:
>>>>>> Hi Troy,
>>>>>>
>>>>>> Looks like we hit the same today -- Sage posted some
observations
>>>>>> here: https://tracker.ceph.com/issues/39525#note-6
>>>>>>
>>>>>> Did it happen again in your cluster?
>>>>>>
>>>>>> Cheers, Dan
>>>>>>
>>>>>>
>>>>>>
>>>>>> On Tue, Aug 20, 2019 at 2:18 AM Troy Ablan
<tablan(a)gmail.com> wrote:
>>>>>>>
>>>>>>> While I'm still unsure how this happened, this is what
was done
>>>>>>> to solve
>>>>>>> this.
>>>>>>>
>>>>>>> Started OSD in foreground with debug 10, watched for the most
>>>>>>> recent
>>>>>>> osdmap epoch mentioned before abort(). For example, if it
>>>>>>> mentioned
>>>>>>> that it just tried to load 80896 and then crashed
>>>>>>>
>>>>>>> # ceph osd getmap -o osdmap.80896 80896
>>>>>>> # ceph-objectstore-tool --op set-osdmap --data-path
>>>>>>> /var/lib/ceph/osd/ceph-77/ --file osdmap.80896
>>>>>>>
>>>>>>> Then I restarted the osd in foreground/debug, and repeated
for
>>>>>>> the next
>>>>>>> osdmap epoch until it got past the first few seconds. This
process
>>>>>>> worked for all but two OSDs. For the ones that succeeded
I'd ^C
>>>>>>> and
>>>>>>> then start the osd via systemd
>>>>>>>
>>>>>>> For the remaining two, it would try loading the incremental
map
>>>>>>> and then
>>>>>>> crash. I had presence of mind to make dd images of every OSD
>>>>>>> before
>>>>>>> starting this process, so I reverted these two to the state
before
>>>>>>> injecting the osdmaps.
>>>>>>>
>>>>>>> I then injected the last 15 or so epochs of the osdmap in
>>>>>>> sequential
>>>>>>> order before starting the osd, with success.
>>>>>>>
>>>>>>> This leads me to believe that the step-wise injection
didn't work
>>>>>>> because the osd had more subtle corruption that it got past,
but
>>>>>>> it was
>>>>>>> confused when it requested the next incremental delta.
>>>>>>>
>>>>>>> Thanks again to Brad/badone for the guidance!
>>>>>>>
>>>>>>> Tracker issue updated.
>>>>>>>
>>>>>>> Here's the closing IRC dialogue re this issue (UTC-0700)
>>>>>>>
>>>>>>> 2019-08-19 16:27:42 < MooingLemur> badone: I appreciate
you
>>>>>>> reaching out
>>>>>>> yesterday, you've helped a ton, twice now :) I'm
still concerned
>>>>>>> because I don't know how this happened. I'll feel
better once
>>>>>>> everything's active+clean, but it's all at least
active.
>>>>>>>
>>>>>>> 2019-08-19 16:30:28 < badone> MooingLemur: I had a
quick
>>>>>>> discussion with
>>>>>>> Josh earlier and he shares my opinion this is likely somehow
>>>>>>> related to
>>>>>>> these drives or perhaps controllers, or at least specific to
>>>>>>> these machines
>>>>>>>
>>>>>>> 2019-08-19 16:31:04 < badone> however, there is a
possibility
>>>>>>> you are
>>>>>>> seeing some extremely rare race that no one up to this point
has
>>>>>>> seen before
>>>>>>>
>>>>>>> 2019-08-19 16:31:20 < badone> that is less likely
though
>>>>>>>
>>>>>>> 2019-08-19 16:32:50 < badone> the osd read the osdmap
over the wire
>>>>>>> successfully but wrote it out to disk in a format that it
could
>>>>>>> not then
>>>>>>> read back in (unlikely) or...
>>>>>>>
>>>>>>> 2019-08-19 16:33:21 < badone> the map
"changed" after it had been
>>>>>>> written to disk
>>>>>>>
>>>>>>> 2019-08-19 16:33:46 < badone> the second is considered
most
>>>>>>> likely by us
>>>>>>> but I recognise you may not share that opinion
>>>>>>> _______________________________________________
>>>>>>> ceph-users mailing list
>>>>>>> ceph-users(a)lists.ceph.com
>>>>>>> http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com