Bug #10819: ceph pg <pgid> mark_unfound_lost revert Causes Primary OSD to Crash - Ceph - Ceph

Actions

Copy link

Bug #10819

closed

ceph pg <pgid> mark_unfound_lost revert Causes Primary OSD to Crash

Added by Mike Dawson about 9 years ago. Updated about 9 years ago.

Status:

Won't Fix

Priority:

Normal

Assignee:

Category:

Target version:

% Done:

Source:

Community (user)

Tags:

Backport:

Regression:

Severity:

3 - minor

Reviewed:

Affected Versions:

ceph-qa-suite:

Pull request ID:

Crash signature (v1):

Crash signature (v2):

Description

On a Dumpling cluster with a missing rbd_header, issuing 'ceph pg <pgid> mark_unfound_lost revert' causes the primary OSD to crash.

ceph health detail | grep unfound
pg 4.653 is active+recovering, acting [5,70,63], 1 unfound

ceph pg 4.653 list_missing { "offset": { "oid": "",
"key": "",
"snapid": 0,
"hash": 0,
"max": 0,
"pool": -1,
"namespace": ""},
"num_missing": 1,
"num_unfound": 1,
"objects": [ { "oid": { "oid": "rbd_header.9e43272eb141f2",
"key": "",
"snapid": -2,
"hash": 1701488211,
"max": 0,
"pool": 4,
"namespace": ""},
"need": "82479'2892808",
"have": "0'0",
"locations": []}],
"more": 0}

ceph pg 4.653 mark_unfound_lost delete
Invalid command: delete not in revert
Error EINVAL: invalid command

ceph pg 4.653 mark_unfound_lost revert

At that point the primary osd crashes with the following backtrace:

10> 2015-02-10 01:53:23.592212 7f466156c700  1 - 10.1.0.4:6807/25399 --> 10.1.0.138:0/6529 -- osd_ping(ping_reply e84956 stamp 2015-02-10 01:53:23.594329) v2 -- ?+0 0x1cbf0380 con 0x1c65a6e0
    9> 2015-02-10 01:53:23.592313 7f466256e700  1 - 10.1.0.4:6808/25399 --> 10.1.0.138:0/6529 -- osd_ping(ping_reply e84956 stamp 2015-02-10 01:53:23.594329) v2 -- ?+0 0x21c7afc0 con 0x1c65b600
    8> 2015-02-10 01:53:23.601126 7f46712e5700  5 --OSD::tracker- reqid: client.12454650.0:104069683, seq: 11175, time: 2015-02-10 01:53:23.601126, event: sub_op_applied, request: osd_sub_op(client.12454650.0:104069683 4.900 407de900/rbd_data.1a54222ae8944a.000000000006049b/head//4 [] v 84956'2957166 snapset=0=[]:[] snapc=0=[]) v7
    7> 2015-02-10 01:53:23.601161 7f46712e5700  5 --OSD::tracker- reqid: client.12454650.0:104069683, seq: 11175, time: 2015-02-10 01:53:23.601161, event: done, request: osd_sub_op(client.12454650.0:104069683 4.900 407de900/rbd_data.1a54222ae8944a.000000000006049b/head//4 [] v 84956'2957166 snapset=0=[]:[] snapc=0=[]) v7
    6> 2015-02-10 01:53:23.613761 7f466a279700  1 - 10.1.0.4:6805/25399 >> :/0 pipe(0x205ec280 sd=76 :6805 s=0 pgs=0 cs=0 l=0 c=0x1ff791e0).accept sd=76 10.1.255.26:50730/0
    5> 2015-02-10 01:53:23.615362 7f4664d73700  1 - 10.1.0.4:6805/25399 <== client.13448331 10.1.255.26:0/1024767 1 ==== command(tid 1: {"prefix": "get_command_descriptions", "pgid": "4.653"}) v1 ==== 79+0+0 (601255400 0 0) 0x1f806000 con 0x1ff791e0
    4> 2015-02-10 01:53:23.615891 7f465d564700  0 osd.5 84956 do_command r=0
    -3> 2015-02-10 01:53:23.615905 7f465d564700  1 - 10.1.0.4:6805/25399 --> 10.1.255.26:0/1024767 -- command_reply(tid 1: 0 ) v1 -- ?+3732 0x1c537a00 con 0x1ff791e0
    2> 2015-02-10 01:53:23.627901 7f4664d73700  1 - 10.1.0.4:6805/25399 <== client.13448331 10.1.255.26:0/1024767 2 ==== command(tid 2: {"mulcmd": "revert", "prefix": "pg", "cmd": "mark_unfound_lost", "pgid": "4.653"}) v1 ==== 105+0+0 (1015902685 0 0) 0x1f7a56c0 con 0x1ff791e0
    -1> 2015-02-10 01:53:23.628113 7f465d564700  3 osd.5 pg_epoch: 84956 pg[4.653( v 84956'3094304 lc 0'0 (82486'2898034,84956'3094304] local-les=84956 n=1662 ec=300 les/c 84956/84953 84955/84955/84955) [5,70,63] r=0 lpr=84955 pi=82478-84954/89 mlcod 0'0 active+recovering MUST_DEEP_SCRUB MUST_SCRUB m=1 u=1] mark_all_unfound_lost l_revert
     0> 2015-02-10 01:53:23.630779 7f465d564700 -1 osd/ReplicatedPG.cc: In function 'eversion_t ReplicatedPG::pick_newest_available(const hobject_t&)' thread 7f465d564700 time 2015-02-10 01:53:23.628157
osd/ReplicatedPG.cc: 6461: FAILED assert(peer  backfill_target)

ceph version 0.67.9 (ba340a97c3dafc9155023da8d515eecc675c619a)
 1: (ReplicatedPG::pick_newest_available(hobject_t const&)+0xa1f) [0x6d1e8f]
 2: (ReplicatedPG::mark_all_unfound_lost(int)+0x773) [0x6e0ee3]
 3: (ReplicatedPG::do_command(std::map&lt;std::string, boost::variant&lt;std::string, bool, long, double, std::vector&lt;std::string, std::allocator&lt;std::string&gt; >, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_>, std::less&lt;std::string&gt;, std::allocator&lt;std::pair&lt;std::string const, boost::variant&lt;std::string, bool, long, double, std::vector&lt;std::string, std::allocator&lt;std::string&gt; >, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_> > > >, std::ostream&, ceph::buffer::list&, ceph::buffer::list&)+0xb04) [0x706f84]
 4: (OSD::do_command(Connection*, unsigned long, std::vector&lt;std::string, std::allocator&lt;std::string&gt; >&, ceph::buffer::list&)+0x1500) [0x767c50]
 5: (OSD::CommandWQ::_process(OSD::Command*)+0x3c) [0x7b37ec]
 6: (ThreadPool::worker(ThreadPool::WorkThread*)+0x68c) [0x9a376c]
 7: (ThreadPool::WorkThread::entry()+0x10) [0x9a49c0]
 8: (()+0x7f8e) [0x7f467e1c3f8e]
 9: (clone()+0x6d) [0x7f467c474a0d]
 NOTE: a copy of the executable, or `objdump -rdS &lt;executable&gt;` 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/ 5 rados
0/ 5 rbd
0/ 5 journaler
0/ 5 objectcacher
0/ 5 client
0/ 5 osd
0/ 5 optracker
0/ 5 objclass
1/ 3 filestore
1/ 3 journal
0/ 5 ms
1/ 5 mon
0/10 monc
1/ 5 paxos
0/ 5 tp
1/ 5 auth
1/ 5 crypto
1/ 1 finisher
1/ 5 heartbeatmap
1/ 5 perfcounter
1/ 5 rgw
1/ 5 hadoop
1/ 5 javaclient
1/ 5 asok
1/ 1 throttle
2/-2 (syslog threshold)
-1/-1 (stderr threshold)
max_recent 10000
max_new 1000
log_file /var/log/ceph/ceph-osd.5.log
-- end dump of recent events ---
2015-02-10 01:53:23.713257 7f465d564700 -1 ** Caught signal (Aborted) *
in thread 7f465d564700

ceph version 0.67.9 (ba340a97c3dafc9155023da8d515eecc675c619a)
 1: /usr/bin/ceph-osd() [0x8ed080]
 2: (()+0xfbd0) [0x7f467e1cbbd0]
 3: (gsignal()+0x37) [0x7f467c3b1037]
 4: (abort()+0x148) [0x7f467c3b4698]
 5: (_gnu_cxx::_verbose_terminate_handler()+0x11d) [0x7f467ccbee8d]
 6: (()+0x5ef76) [0x7f467ccbcf76]
 7: (()+0x5efa3) [0x7f467ccbcfa3]
 8: (()+0x5f1de) [0x7f467ccbd1de]
 9: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x43d) [0x9b1bfd]
 10: (ReplicatedPG::pick_newest_available(hobject_t const&)+0xa1f) [0x6d1e8f]
 11: (ReplicatedPG::mark_all_unfound_lost(int)+0x773) [0x6e0ee3]
 12: (ReplicatedPG::do_command(std::map&lt;std::string, boost::variant&lt;std::string, bool, long, double, std::vector&lt;std::string, std::allocator&lt;std::string&gt; >, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_>, std::less&lt;std::string&gt;, std::allocator&lt;std::pair&lt;std::string const, boost::variant&lt;std::string, bool, long, double, std::vector&lt;std::string, std::allocator&lt;std::string&gt; >, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_> > > >, std::ostream&, ceph::buffer::list&, ceph::buffer::list&)+0xb04) [0x706f84]
 13: (OSD::do_command(Connection*, unsigned long, std::vector&lt;std::string, std::allocator&lt;std::string&gt; >&, ceph::buffer::list&)+0x1500) [0x767c50]
 14: (OSD::CommandWQ::_process(OSD::Command*)+0x3c) [0x7b37ec]
 15: (ThreadPool::worker(ThreadPool::WorkThread*)+0x68c) [0x9a376c]
 16: (ThreadPool::WorkThread::entry()+0x10) [0x9a49c0]
 17: (()+0x7f8e) [0x7f467e1c3f8e]
 18: (clone()+0x6d) [0x7f467c474a0d]
 NOTE: a copy of the executable, or `objdump -rdS &lt;executable&gt;` is needed to interpret this.

--- begin dump of recent events ---
~~17> 2015-02-10 01:53:23.674732 7f466256e700 1 -~~ 10.1.0.4:6808/25399 < osd.44 10.1.0.130:0/22625 97 ==== osd_ping(ping e84956 stamp 2015-02-10 01:53:23.673896) v2 ==== 47+0+0 (3453591129 0 0) 0x1ce73500 con 0x17596c60
~~16> 2015-02-10 01:53:23.674767 7f466256e700 1 -~~ 10.1.0.4:6808/25399 --> 10.1.0.130:0/22625 -- osd_ping(ping_reply e84956 stamp 2015-02-10 01:53:23.673896) v2 -- ?+0 0x1f079500 con 0x17596c60
~~15> 2015-02-10 01:53:23.674784 7f466156c700 1 -~~ 10.1.0.4:6807/25399 <== osd.44 10.1.0.130:0/22625 97 ==== osd_ping(ping e84956 stamp 2015-02-10 01:53:23.673896) v2 ==== 47+0+0 (3453591129 0 0) 0x1df17340 con 0x1eb49080
~~14> 2015-02-10 01:53:23.674810 7f466156c700 1 -~~ 10.1.0.4:6807/25399 --> 10.1.0.130:0/22625 -- osd_ping(ping_reply e84956 stamp 2015-02-10 01:53:23.673896) v2 -- ?+0 0x1e1bcfc0 con 0x1eb49080
~~13> 2015-02-10 01:53:23.675056 7f466156c700 1 -~~ 10.1.0.4:6807/25399 <== osd.37 10.1.0.72:0/8537 109 ==== osd_ping(ping e84956 stamp 2015-02-10 01:53:23.674776) v2 ==== 47+0+0 (1206102692 0 0) 0x1b3a56c0 con 0x1c764f20
~~12> 2015-02-10 01:53:23.675060 7f466256e700 1 -~~ 10.1.0.4:6808/25399 <== osd.37 10.1.0.72:0/8537 109 ==== osd_ping(ping e84956 stamp 2015-02-10 01:53:23.674776) v2 ==== 47+0+0 (1206102692 0 0) 0x1eb28380 con 0x1bd74160
~~11> 2015-02-10 01:53:23.675087 7f466156c700 1 -~~ 10.1.0.4:6807/25399 --> 10.1.0.72:0/8537 -- osd_ping(ping_reply e84956 stamp 2015-02-10 01:53:23.674776) v2 -- ?+0 0x1df17340 con 0x1c764f20
~~10> 2015-02-10 01:53:23.675217 7f466256e700 1 -~~ 10.1.0.4:6808/25399 --> 10.1.0.72:0/8537 -- osd_ping(ping_reply e84956 stamp 2015-02-10 01:53:23.674776) v2 -- ?+0 0x1ce73500 con 0x1bd74160
~~9> 2015-02-10 01:53:23.677519 7f4663d71700 1 -~~ 10.1.0.4:6806/25399 <== osd.21 10.1.0.67:6813/24291 211 ==== osd_sub_op(client.12870837.0:31389842 4.cf2 1ff06cf2/rbd_data.1bff6d2ae8944a.0000000000040e6f/head//4 [] v 84956'2776081 snapset=0=[]:[] snapc=0=[]) v7 ==== 1173+0+16527 (1580365688 0 3982498322) 0x20efbe00 con 0x1b372b00
~~8> 2015-02-10 01:53:23.679459 7f466156c700 1 -~~ 10.1.0.4:6807/25399 <== osd.54 10.1.0.134:0/4748 107 ==== osd_ping(ping e84956 stamp 2015-02-10 01:53:23.678755) v2 ==== 47+0+0 (2400717333 0 0) 0x1f70b180 con 0x1c65ac60
~~7> 2015-02-10 01:53:23.679485 7f466156c700 1 -~~ 10.1.0.4:6807/25399 --> 10.1.0.134:0/4748 -- osd_ping(ping_reply e84956 stamp 2015-02-10 01:53:23.678755) v2 -- ?+0 0x1b3a56c0 con 0x1c65ac60
~~6> 2015-02-10 01:53:23.679549 7f466256e700 1 -~~ 10.1.0.4:6808/25399 <== osd.54 10.1.0.134:0/4748 107 ==== osd_ping(ping e84956 stamp 2015-02-10 01:53:23.678755) v2 ==== 47+0+0 (2400717333 0 0) 0xd342700 con 0x1c65bb80
~~5> 2015-02-10 01:53:23.679569 7f466256e700 1 -~~ 10.1.0.4:6808/25399 --> 10.1.0.134:0/4748 -- osd_ping(ping_reply e84956 stamp 2015-02-10 01:53:23.678755) v2 -- ?+0 0x1eb28380 con 0x1c65bb80
~~4> 2015-02-10 01:53:23.703534 7f466156c700 1 -~~ 10.1.0.4:6807/25399 <== osd.51 10.1.0.133:0/4126 96 ==== osd_ping(ping e84956 stamp 2015-02-10 01:53:23.702918) v2 ==== 47+0+0 (1721923101 0 0) 0x1ca54e00 con 0x1c7649a0
~~3> 2015-02-10 01:53:23.703545 7f466256e700 1 -~~ 10.1.0.4:6808/25399 <== osd.51 10.1.0.133:0/4126 96 ==== osd_ping(ping e84956 stamp 2015-02-10 01:53:23.702918) v2 ==== 47+0+0 (1721923101 0 0) 0x1da8b340 con 0x1c7651e0
~~2> 2015-02-10 01:53:23.703569 7f466156c700 1 -~~ 10.1.0.4:6807/25399 --> 10.1.0.133:0/4126 -- osd_ping(ping_reply e84956 stamp 2015-02-10 01:53:23.702918) v2 -- ?+0 0x1f70b180 con 0x1c7649a0
~~1> 2015-02-10 01:53:23.703641 7f466256e700 1 -~~ 10.1.0.4:6808/25399 --> 10.1.0.133:0/4126 -- osd_ping(ping_reply e84956 stamp 2015-02-10 01:53:23.702918) v2 -- ?+0 0xd342700 con 0x1c7651e0
0> 2015-02-10 01:53:23.713257 7f465d564700 -1 ** Caught signal (Aborted) *
in thread 7f465d564700

ceph version 0.67.9 (ba340a97c3dafc9155023da8d515eecc675c619a)
 1: /usr/bin/ceph-osd() [0x8ed080]
 2: (()+0xfbd0) [0x7f467e1cbbd0]
 3: (gsignal()+0x37) [0x7f467c3b1037]
 4: (abort()+0x148) [0x7f467c3b4698]
 5: (_gnu_cxx::_verbose_terminate_handler()+0x11d) [0x7f467ccbee8d]
 6: (()+0x5ef76) [0x7f467ccbcf76]
 7: (()+0x5efa3) [0x7f467ccbcfa3]
 8: (()+0x5f1de) [0x7f467ccbd1de]
 9: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x43d) [0x9b1bfd]
 10: (ReplicatedPG::pick_newest_available(hobject_t const&)+0xa1f) [0x6d1e8f]
 11: (ReplicatedPG::mark_all_unfound_lost(int)+0x773) [0x6e0ee3]
 12: (ReplicatedPG::do_command(std::map&lt;std::string, boost::variant&lt;std::string, bool, long, double, std::vector&lt;std::string, std::allocator&lt;std::string&gt; >, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_>, std::less&lt;std::string&gt;, std::allocator&lt;std::pair&lt;std::string const, boost::variant&lt;std::string, bool, long, double, std::vector&lt;std::string, std::allocator&lt;std::string&gt; >, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_> > > >, std::ostream&, ceph::buffer::list&, ceph::buffer::list&)+0xb04) [0x706f84]
 13: (OSD::do_command(Connection*, unsigned long, std::vector&lt;std::string, std::allocator&lt;std::string&gt; >&, ceph::buffer::list&)+0x1500) [0x767c50]
 14: (OSD::CommandWQ::_process(OSD::Command*)+0x3c) [0x7b37ec]
 15: (ThreadPool::worker(ThreadPool::WorkThread*)+0x68c) [0x9a376c]
 16: (ThreadPool::WorkThread::entry()+0x10) [0x9a49c0]
 17: (()+0x7f8e) [0x7f467e1c3f8e]
 18: (clone()+0x6d) [0x7f467c474a0d]
 NOTE: a copy of the executable, or `objdump -rdS &lt;executable&gt;` is needed to interpret this.

Actions

Copy link

Updated by Samuel Just about 9 years ago

Status changed from New to Won't Fix

This works differently in newer versions.

Actions

Copy link

Updated by Sage Weil about 9 years ago

Status changed from Won't Fix to New

if this is preventing hte osd from restarting too we can prioritize a fix...

Actions

Copy link

Updated by Sage Weil about 9 years ago

Status changed from New to Won't Fix

Actions

Copy link

Updated by Mike Dawson about 9 years ago

Sage, it isn't preventing the OSD from restarting, so that isn't an issue. But, without an upgrade past Dumpling, I don't have a clear method to resolve the unfound object.

I've worked with Josh on a method to rebuild the missing rbd_header, but on 0.67.9, I cannot 'rados put' or 'rados rm' the missing rbd_header.9e43272eb141f2 because those commands hang indefinitely. Our theory was resolving the this unfound object was the most obvious path forward. Suggestions?

Actions

Copy link

Also available in: Atom PDF

Project

General

Profile

Ceph

Custom queries

Bug #10819

ceph pg <pgid> mark_unfound_lost revert Causes Primary OSD to Crash

Updated by Samuel Just about 9 years ago

Updated by Sage Weil about 9 years ago

Updated by Sage Weil about 9 years ago

Updated by Mike Dawson about 9 years ago