Bug #22114
closedmon: ops get stuck in "resend forwarded message to leader"
0%
Description
some ops get stuck in "resend forwarded message to leader" for days.
{ "description": "osd_pg_created(1.7d2)", "initiated_at": "2017-11-07 16:51:41.018915", "age": 494016.079968, "duration": 494016.100409, "type_data": { "events": [ { "time": "2017-11-07 16:51:41.018915", "event": "initiated" }, { "time": "2017-11-07 16:51:41.018915", "event": "mon:_ms_dispatch" }, { "time": "2017-11-07 16:51:41.018916", "event": "mon:dispatch_op" }, { "time": "2017-11-07 16:51:41.018916", "event": "psvc:dispatch" }, { "time": "2017-11-07 16:51:41.018916", "event": "osdmap:preprocess_query" }, { "time": "2017-11-07 16:51:41.018916", "event": "osdmap:preprocess_pg_created" }, { "time": "2017-11-07 16:51:41.018916", "event": "forward_request_leader" }, { "time": "2017-11-07 16:51:41.018920", "event": "forwarded" }, { "time": "2017-11-10 14:40:38.489281", "event": "resend forwarded message to leader" }, { "time": "2017-11-10 15:25:34.712647", "event": "resend forwarded message to leader" }, { "time": "2017-11-10 15:49:44.912601", "event": "resend forwarded message to leader" }, { "time": "2017-11-10 15:49:47.615925", "event": "resend forwarded message to leader" }, { "time": "2017-11-10 17:01:26.958438", "event": "resend forwarded message to leader" }, { "time": "2017-11-10 17:43:39.204785", "event": "resend forwarded message to leader" }, { "time": "2017-11-10 17:46:24.955425", "event": "resend forwarded message to leader" }, { "time": "2017-11-10 18:08:14.914648", "event": "resend forwarded message to leader" }, { "time": "2017-11-10 18:19:58.752120", "event": "resend forwarded message to leader" }, { "time": "2017-11-10 18:23:31.995804", "event": "resend forwarded message to leader" }, { "time": "2017-11-10 18:47:32.106938",
And the memory of mon daemon grew huge
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 3731 root 20 0 13.194g *9.998g* 8204 S 0.7 34.9 194:05.72 ceph-mon
Updated by hongpeng lu over 6 years ago
cluster is normal.
[root@node-113 ~]# ceph -s cluster: id: 76d145e9-007f-42d5-8908-dceb91e141ae health: HEALTH_OK services: mon: 3 daemons, quorum node-110,node-113,node-114 mgr: node-110(active), standbys: node-113, node-114 osd: 144 osds: 120 up, 120 in flags noscrub,nodeep-scrub data: pools: 2 pools, 3072 pgs objects: 12820k objects, 50937 GB usage: 64727 GB used, 154 TB / 218 TB avail pgs: 3072 active+clean
Updated by Greg Farnum over 6 years ago
- Subject changed from ops get stuck in "resend forwarded message to leader" to mon: ops get stuck in "resend forwarded message to leader"
- Assignee set to Joao Eduardo Luis
What version are you running? This sounds like a known issue but it was fixed long ago.
Updated by hongpeng lu over 6 years ago
Greg Farnum wrote:
What version are you running? This sounds like a known issue but it was fixed long ago.
[root@node-114 ~]# ceph -v
ceph version 12.2.0 (32ce2a3ae5239ee33d6150705cdb24d43bab910c) luminous (rc)
Updated by hongpeng lu over 6 years ago
Greg Farnum wrote:
What version are you running? This sounds like a known issue but it was fixed long ago.
Can you give me more information about the known issue? Maybe I can confirm the problem by myself first.
Updated by Greg Farnum over 6 years ago
Hmm, nope, it's definitely something different if it's happening in Luminous.
Updated by hongpeng lu over 6 years ago
It happended again.
[root@iozone-103 ~]# ceph daemon mon.iozone-103 ops |more { "ops": [ { "description": "mgrbeacon mgr.iozone-102(512854e7-da3e-4cfb-9565-4d7f98457857,3234103, 60.60.1.102:6800/4121, 1)", "initiated_at": "2017-11-23 11:22:30.243184", "age": 11072.890211, "duration": 11072.890229, "type_data": { "events": [ { "time": "2017-11-23 11:22:30.243184", "event": "initiated" }, { "time": "2017-11-23 11:22:30.243189", "event": "mon:_ms_dispatch" }, { "time": "2017-11-23 11:22:30.243190", "event": "mon:dispatch_op" }, { "time": "2017-11-23 11:22:30.243191", "event": "psvc:dispatch" }, { "time": "2017-11-23 11:22:30.243195", "event": "forward_request_leader" }, { "time": "2017-11-23 11:22:30.243215", "event": "forwarded" }, { "time": "2017-11-23 14:25:27.653030", "event": "resend forwarded message to leader" } ], "info": { "seq": 842, "src_is_mon": false, "source": "client.3234103 60.60.1.102:0/3512721476", "forwarded_to_leader": true } } }, admin_socket: [Errno 32] Broken pipe [root@iozone-103 ~]# date Thu Nov 23 14:28:08 CST 2017
Updated by hongpeng lu over 6 years ago
Captured monitor's log
2017-11-23 19:03:54.327344 7fc81420d700 10 mon.iozone-101@0(leader) e1 received forwarded message from osd.9 60.60.1.102:6801/314 via mon.2 60.60.1.103:6789/0
2017-11-23 19:03:54.327346 7fc81420d700 20 is_capable service=mon command= exec on cap allow *
2017-11-23 19:03:54.327347 7fc81420d700 20 allow so far , doing grant allow *
2017-11-23 19:03:54.327347 7fc81420d700 20 allow all
2017-11-23 19:03:54.327349 7fc81420d700 10 mon.iozone-101@0(leader) e1 caps are allow *
2017-11-23 19:03:54.327350 7fc81420d700 10 mon.iozone-101@0(leader) e1 entity name '' type 0
2017-11-23 19:03:54.327351 7fc81420d700 10 mon.iozone-101@0(leader) e1 mesg 0x7fc82bd3aac0 from 60.60.1.103:6789/0
2017-11-23 19:03:54.327352 7fc81420d700 20 mon.iozone-101@0(leader) e1 _ms_dispatch existing session 0x7fc82c7a2580 for osd.9 -
2017-11-23 19:03:54.327353 7fc81420d700 20 mon.iozone-101@0(leader) e1 caps allow *
2017-11-23 19:03:54.327354 7fc81420d700 10 mon.iozone-101@0(leader).paxosservice(osdmap 504..1814) dispatch 0x7fc82bd3aac0 osd_beacon(pgs [4.12f,4.aa,4.153,4.39,4.15d,4.2b,4.29,4.1b,4.1d4,4.3d,4.154] lec 1573 v1666) v1 from osd.9 60.60.1.102:6801/314 con 0x7fc82fb2de00
2017-11-23 19:03:54.327357 7fc81420d700 5 mon.iozone-101@0(leader).paxos(paxos recovering c 2289121..2289813) is_readable = 0 - now=2017-11-23 19:03:54.327357 lease_expire=0.000000 has v0 lc 2289813
2017-11-23 19:03:54.327359 7fc81420d700 10 mon.iozone-101@0(leader).paxosservice(osdmap 504..1814) waiting for paxos -> readable (v1666)
2017-11-23 19:03:54.327361 7fc81420d700 5 mon.iozone-101@0(leader).paxos(paxos recovering c 2289121..2289813) is_readable = 0 - now=2017-11-23 19:03:54.327361 lease_expire=0.000000 has v0 lc 2289813
2017-11-23 19:03:54.327367 7fc81420d700 20 mon.iozone-101@0(leader) e1 _ms_dispatch existing session 0x7fc826c06600 for mon.2 60.60.1.103:6789/0
2017-11-23 19:03:54.327369 7fc81420d700 20 mon.iozone-101@0(leader) e1 caps allow *
2017-11-23 19:03:54.327370 7fc81420d700 20 is_capable service=mon command= read on cap allow *
2017-11-23 19:03:54.327370 7fc81420d700 20 allow so far , doing grant allow *
I'm confuse about why leader's lease_expire is equal 0 when handling the forwared message.
Updated by hongpeng lu over 6 years ago
Greg Farnum wrote:
Hmm, nope, it's definitely something different if it's happening in Luminous.
I changed some code in function Monitor::dispatch_op, and the op which's type is mgrbeacon never stuck again.
maybe we forget to replay mon that forwards the message?
case MSG_MGR_BEACON:
paxos_service[PAXOS_MGR]->dispatch(op);
no_reply(op); //add to test the issue
Updated by Greg Farnum over 6 years ago
Ummm, yep, that looks right to me at a quick glance! Can you submit a PR with that change? :)
Updated by hongpeng lu over 6 years ago
Greg Farnum wrote:
Ummm, yep, that looks right to me at a quick glance! Can you submit a PR with that change? :)
Hmm, actually, I don't know how to submit a PR.
By the way, messages such as MSD_OSD_PG_CRETEAED and MSG_OSD_BEACON may have the same issue.
Updated by Nathan Cutler over 6 years ago
hongpeng lu wrote:
Hmm, actually, I don't know how to submit a PR.
https://github.com/ceph/ceph/blob/master/SubmittingPatches.rst#1-github-pull-request
Updated by Oleg Glushak about 6 years ago
We have the same problem on all our Luminous clusters. Any news regarding fix?
Most stuck messages in our case are osd_beacon.
Is there any workaround? E.g. could we set timeout for these messages?
Updated by hongpeng lu about 6 years ago
The messages can not be forwarded appropriately, you must change the code like this.
case MSG_MGR_BEACON: paxos_service[PAXOS_MGR]->dispatch(op); no_reply(op);
Updated by Oleg Glushak about 6 years ago
hongpeng lu wrote:
The messages can not be forwarded appropriately, you must change the code like this.
[...]
Thx for the quick reply! Is there already PR exist to fix this issue?
Updated by hongpeng lu about 6 years ago
Maybe not. you should check the code on github.com.
Updated by hongpeng lu about 6 years ago
Greg Farnum wrote:
Ummm, yep, that looks right to me at a quick glance! Can you submit a PR with that change? :)
sorry, I can't test my code because I don't have mechines to run a cluster. I quited my jop few months ago.
I'm afraid that you must do it by youself.
Updated by Greg Farnum about 6 years ago
- Status changed from 12 to Fix Under Review
- Assignee changed from Joao Eduardo Luis to Greg Farnum
Updated by Sage Weil about 6 years ago
- Status changed from Fix Under Review to Pending Backport
- Backport set to luminous
Updated by Greg Farnum about 6 years ago
Oh, second PR for the OSD beacons and PG create messages: https://github.com/ceph/ceph/pull/20517
Updated by Nathan Cutler about 6 years ago
- Copied to Backport #23077: luminous: mon: ops get stuck in "resend forwarded message to leader" added
Updated by Kefu Chai about 6 years ago
- Status changed from Pending Backport to Fix Under Review
- Assignee changed from Greg Farnum to Kefu Chai
Updated by Kefu Chai about 6 years ago
- Status changed from Fix Under Review to Pending Backport
Updated by Nathan Cutler about 6 years ago
- Status changed from Pending Backport to Resolved
Updated by Jiaxing Fan about 2 years ago
I hited this bug in octopus.
"description": "log(2 entries from seq 1 at 2021-12-20T10:43:38.225243+0800)",
"initiated_at": "2021-12-20T10:43:40.490982+0800",
"age": 6306340.1792147979,
"duration": 6306340.179250556,
{
"time": "2021-12-28T08:07:22.952481+0800",
"event": "resend forwarded message to leader"
},
{
"time": "2021-12-29T08:07:28.266030+0800",
"event": "resend forwarded message to leader"
},
I think there is other reason for this bug: we don't remove forward requests belong to keepalive session when trimming mon sessions.
By the way, I also think routed_requests should be protected by a lock.
Updated by Radoslaw Zarzynski about 2 years ago
- Related to Bug #54489: mon: ops get stuck in "resend forwarded message to leader" added