Project

General

Profile

Bug #16672

OSD crash with Hammer to Jewel Upgrade: void FileStore::init_temp_collections()

Added by Wido den Hollander over 2 years ago. Updated over 2 years ago.

Status:
Resolved
Priority:
Urgent
Assignee:
Category:
OSD
Target version:
-
Start date:
07/13/2016
Due date:
% Done:

0%

Source:
other
Tags:
osd,hammer,jewel,upgrade
Backport:
jewel
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Pull request ID:

Description

During a upgrade from 0.94.7 to 10.2.2 I'm seeing multiple OSDs crash with this backtrace:

-7> 2016-07-13 10:23:42.811650 7f3f5fd0c800  0 genericfilestorebackend(/var/lib/ceph/osd/ceph-476) detect_features: splice is supported
-6> 2016-07-13 10:23:42.843643 7f3f5fd0c800  0 genericfilestorebackend(/var/lib/ceph/osd/ceph-476) detect_features: syncfs(2) syscall fully supported (by glibc and kernel)
-5> 2016-07-13 10:23:42.844736 7f3f5fd0c800  0 xfsfilestorebackend(/var/lib/ceph/osd/ceph-476) detect_feature: extsize is disabled by conf
-4> 2016-07-13 10:23:42.847300 7f3f5fd0c800  1 leveldb: Recovering log #876
-3> 2016-07-13 10:23:42.894086 7f3f5fd0c800  1 leveldb: Delete type=0 #876

-2> 2016-07-13 10:23:42.894171 7f3f5fd0c800  1 leveldb: Delete type=3 #875

-1> 2016-07-13 10:23:42.895373 7f3f5fd0c800  0 filestore(/var/lib/ceph/osd/ceph-476) mount: enabling WRITEAHEAD journal mode: checkpoint is not enabled
 0> 2016-07-13 10:23:42.905145 7f3f5fd0c800 -1 os/filestore/FileStore.cc: In function 'void FileStore::init_temp_collections()' thread 7f3f5fd0c800 time 2016-07-13 10:23:42.902566
os/filestore/FileStore.cc: 1735: FAILED assert(r == 0)

ceph version 10.2.2 (45107e21c568dd033c2f0a3107dec8f0b0e58374)
1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x85) [0x7f3f607375b5]
2: (FileStore::init_temp_collections()+0xa63) [0x7f3f603ff613]
3: (FileStore::mount()+0x3ed0) [0x7f3f604036d0]
4: (OSD::init()+0x27d) [0x7f3f600c704d]
5: (main()+0x2c55) [0x7f3f6002cbe5]
6: (__libc_start_main()+0xf5) [0x7f3f5cc1eb15]
7: (()+0x353009) [0x7f3f60077009]
NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.

--- logging levels ---
0/ 5 none
0/ 1 lockdep
0/ 1 context
1/ 1 crush
1/ 5 mds
1/ 5 mds_balancer
1/ 5 mds_locker
1/ 5 mds_log
1/ 5 mds_log_expire
1/ 5 mds_migrator
0/ 1 buffer
0/ 1 timer
0/ 1 filer
0/ 1 striper
0/ 1 objecter
0/ 0 rados
0/ 0 rbd
0/ 5 rbd_mirror
0/ 5 rbd_replay
0/ 5 journaler
0/ 5 objectcacher
0/ 5 client
0/ 0 osd
0/ 5 optracker
0/ 5 objclass
0/ 0 filestore
0/ 0 journal
0/ 0 ms
1/ 5 mon
0/10 monc
1/ 5 paxos
0/ 5 tp
0/ 0 auth
1/ 5 crypto
1/ 1 finisher
1/ 5 heartbeatmap
1/ 5 perfcounter
1/ 5 rgw
1/10 civetweb
1/ 5 javaclient
1/ 5 asok
1/ 1 throttle
0/ 0 refs
1/ 5 xio
1/ 5 compressor
1/ 5 newstore
1/ 5 bluestore
1/ 5 bluefs
1/ 3 bdev
1/ 5 kstore
4/ 5 rocksdb
4/ 5 leveldb
1/ 5 kinetic
1/ 5 fuse
-2/-2 (syslog threshold)
-1/-1 (stderr threshold)
max_recent     10000
max_new         1000
log_file /var/log/ceph/ceph-osd.476.log
--- end dump of recent events ---
2016-07-13 10:23:42.909150 7f3f5fd0c800 -1 *** Caught signal (Aborted) **
in thread 7f3f5fd0c800 thread_name:ceph-osd

ceph version 10.2.2 (45107e21c568dd033c2f0a3107dec8f0b0e58374)
1: (()+0x91341a) [0x7f3f6063741a]
2: (()+0xf100) [0x7f3f5e66f100]
3: (gsignal()+0x37) [0x7f3f5cc325f7]
4: (abort()+0x148) [0x7f3f5cc33ce8]
5: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x267) [0x7f3f60737797]
6: (FileStore::init_temp_collections()+0xa63) [0x7f3f603ff613]
7: (FileStore::mount()+0x3ed0) [0x7f3f604036d0]
8: (OSD::init()+0x27d) [0x7f3f600c704d]
9: (main()+0x2c55) [0x7f3f6002cbe5]
10: (__libc_start_main()+0xf5) [0x7f3f5cc1eb15]
11: (()+0x353009) [0x7f3f60077009]
NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.

--- begin dump of recent events ---
 0> 2016-07-13 10:23:42.909150 7f3f5fd0c800 -1 *** Caught signal (Aborted) **
in thread 7f3f5fd0c800 thread_name:ceph-osd

ceph version 10.2.2 (45107e21c568dd033c2f0a3107dec8f0b0e58374)
1: (()+0x91341a) [0x7f3f6063741a]
2: (()+0xf100) [0x7f3f5e66f100]
3: (gsignal()+0x37) [0x7f3f5cc325f7]
4: (abort()+0x148) [0x7f3f5cc33ce8]
5: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x267) [0x7f3f60737797]
6: (FileStore::init_temp_collections()+0xa63) [0x7f3f603ff613]
7: (FileStore::mount()+0x3ed0) [0x7f3f604036d0]
8: (OSD::init()+0x27d) [0x7f3f600c704d]
9: (main()+0x2c55) [0x7f3f6002cbe5]
10: (__libc_start_main()+0xf5) [0x7f3f5cc1eb15]
11: (()+0x353009) [0x7f3f60077009]
NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.

--- logging levels ---
0/ 5 none
0/ 1 lockdep
0/ 1 context
1/ 1 crush
1/ 5 mds
1/ 5 mds_balancer
1/ 5 mds_locker
1/ 5 mds_log
1/ 5 mds_log_expire
1/ 5 mds_migrator
0/ 1 buffer
0/ 1 timer
0/ 1 filer
0/ 1 striper
0/ 1 objecter
0/ 0 rados
0/ 0 rbd
0/ 5 rbd_mirror
0/ 5 rbd_replay
0/ 5 journaler
0/ 5 objectcacher
0/ 5 client
0/ 0 osd
0/ 5 optracker
0/ 5 objclass
0/ 0 filestore
0/ 0 journal
0/ 0 ms
1/ 5 mon
0/10 monc
1/ 5 paxos
0/ 5 tp
0/ 0 auth
1/ 5 crypto
1/ 1 finisher
1/ 5 heartbeatmap
1/ 5 perfcounter
1/ 5 rgw
1/10 civetweb
1/ 5 javaclient
1/ 5 asok
1/ 1 throttle
0/ 0 refs
1/ 5 xio
1/ 5 compressor
1/ 5 newstore
1/ 5 bluestore
1/ 5 bluefs
1/ 3 bdev
1/ 5 kstore
4/ 5 rocksdb
4/ 5 leveldb
1/ 5 kinetic
1/ 5 fuse
-2/-2 (syslog threshold)
-1/-1 (stderr threshold)
max_recent     10000
max_new         1000
log_file /var/log/ceph/ceph-osd.476.log
--- end dump of recent events ---

If I try to start them again it works, but sometimes requires two additional tries.

systemctl reset-failed ceph-osd@476.service
systemctl start ceph-osd@476.service

It is a bit hard to diagnose since it doesn't happen on all OSDs and it doesn't always happen a second time on the same OSD.


Related issues

Copied to Ceph - Backport #16915: Jewel: OSD crash with Hammer to Jewel Upgrade: void FileStore::init_temp_collections() Resolved

History

#1 Updated by Samuel Just over 2 years ago

We'll need debugging when it happens:

debug osd = 20
debug filestore = 20
debug ms = 1

#2 Updated by Wido den Hollander over 2 years ago

I understand. The problem is, it's now no longer happening on the nodes I'm still upgrading...

#3 Updated by Eric Cook over 2 years ago

Samuel Just wrote:

We'll need debugging when it happens:

debug osd = 20
debug filestore = 20
debug ms = 1

I am currently running into this issue with a handful of osds. I've recreated a few osds that exhibited issue as a workaround but that isn't ideal.
I've attached the log of an osd with those debug levels, i can keep an broken osd around if needed.

#4 Updated by Eric Cook over 2 years ago

since my log file was over the limit i used ceph-post-file.
ceph-post-file: 3dc42022-1e9f-42ea-97c4-ad8a30e90fa1

#5 Updated by Jimmy Goffaux over 2 years ago

Hello
Last month I made fifteen times the upgrade on my dev platform and last week production without problems.
Today I have this bug on my platform developement after an upgrade (Hammer to Jewel)

My servers are ubuntu 14.04
Ceph: 0.94.7 to 10.2.2

I can provide logs if you want.

#6 Updated by Eric Cook over 2 years ago

Two more osds:
ceph-post-file: 3a0db99a-556d-478c-a4bd-927413c18762
ceph-post-file: 088e0d65-1a2c-4857-aedd-d38b4d9ea1a2

Seems like _destroy_collection trys to delete a pg that doesn't exist, then dies after failing.

#7 Updated by Samuel Just over 2 years ago

  • Priority changed from Normal to Urgent

#8 Updated by Samuel Just over 2 years ago

  • Assignee set to David Zafman

#9 Updated by David Zafman over 2 years ago

  • Status changed from New to In Progress

I can reproduce this crash by creating a _TEMP directory when there isn't a _head for that pg on the osd. What I find is that HashIndex::prep_delete() causes a rmdir to occur which then causes the ::rmdir() in FileStore::_destroy_collection() to get an ENOENT. This also explains why an OSD restart comes up without an error.

#0  rmdir () at ../sysdeps/unix/syscall-template.S:81
#1  0x0000555555c372cb in LFNIndex::remove_path (this=this@entry=0x55555f61beb0, to_remove=std::vector of length 0, capacity 0) at os/filestore/LFNIndex.cc:503
#2  0x0000555555ce67ab in HashIndex::recursive_remove (this=0x55555f61beb0, path=std::vector of length 0, capacity 0) at os/filestore/HashIndex.cc:573
#3  0x0000555555ce68e2 in HashIndex::prep_delete (this=<optimized out>) at os/filestore/HashIndex.cc:402
#4  0x0000555555be83d7 in FileStore::_destroy_collection (this=0x55555f594150, c=...) at os/filestore/FileStore.cc:5089
#5  0x0000555555c085c1 in FileStore::_collection_remove_recursive (this=0x55555f594150, cid=..., spos=...) at os/filestore/FileStore.cc:4620
#6  0x0000555555c08d3a in FileStore::init_temp_collections (this=0x55555f594150) at os/filestore/FileStore.cc:1734
#7  0x0000555555c0d265 in FileStore::mount (this=0x55555f594150) at os/filestore/FileStore.cc:1649
#8  0x00005555558ed8cd in OSD::init (this=0x55555f5f6c80) at osd/OSD.cc:2004
#9  0x0000555555858230 in main (argc=<optimized out>, argv=<optimized out>) at ceph_osd.cc:605

#11 Updated by Samuel Just over 2 years ago

Here's a question: did anyone recently perform pg splits?

#12 Updated by Samuel Just over 2 years ago

By pg split, I mean increasing the pg_num and pgp_num on a pool.

#13 Updated by Samuel Just over 2 years ago

And is it possible that the osds which crashed hadn't been restarted since the pg_num/pgp_num change?

#14 Updated by David Zafman over 2 years ago

  • Backport set to jewel

#15 Updated by David Zafman over 2 years ago

  • Copied to Backport #16915: Jewel: OSD crash with Hammer to Jewel Upgrade: void FileStore::init_temp_collections() added

#16 Updated by David Zafman over 2 years ago

  • Status changed from In Progress to Pending Backport

#17 Updated by David Zafman over 2 years ago

  • Status changed from Pending Backport to Resolved

Also available in: Atom PDF