Project

General

Profile

Bug #22114

mon: ops get stuck in "resend forwarded message to leader"

Added by hongpeng lu over 1 year ago. Updated about 1 year ago.

Status:
Resolved
Priority:
Normal
Assignee:
Category:
-
Target version:
-
Start date:
11/13/2017
Due date:
% Done:

0%

Source:
Tags:
Backport:
luminous
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Component(RADOS):
Monitor
Pull request ID:

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

Related issues

Copied to RADOS - Backport #23077: luminous: mon: ops get stuck in "resend forwarded message to leader" Resolved

History

#1 Updated by hongpeng lu over 1 year 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

#2 Updated by Greg Farnum over 1 year 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.

#3 Updated by hongpeng lu over 1 year 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)

#4 Updated by hongpeng lu over 1 year 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.

#5 Updated by Greg Farnum over 1 year ago

Hmm, nope, it's definitely something different if it's happening in Luminous.

#6 Updated by hongpeng lu over 1 year 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

#7 Updated by hongpeng lu over 1 year 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.

#8 Updated by hongpeng lu over 1 year 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

#9 Updated by Greg Farnum over 1 year ago

Ummm, yep, that looks right to me at a quick glance! Can you submit a PR with that change? :)

#10 Updated by Greg Farnum over 1 year ago

  • Status changed from New to Verified

#11 Updated by hongpeng lu over 1 year 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.

#12 Updated by Nathan Cutler over 1 year 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

#13 Updated by Oleg Glushak over 1 year 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?

#14 Updated by hongpeng lu over 1 year 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);

#15 Updated by Oleg Glushak over 1 year 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?

#16 Updated by hongpeng lu over 1 year ago

Maybe not. you should check the code on github.com.

#17 Updated by hongpeng lu over 1 year 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.

#18 Updated by Greg Farnum over 1 year ago

  • Status changed from Verified to Need Review
  • Assignee changed from Joao Eduardo Luis to Greg Farnum

#19 Updated by Sage Weil over 1 year ago

  • Status changed from Need Review to Pending Backport
  • Backport set to luminous

#20 Updated by Greg Farnum over 1 year ago

Oh, second PR for the OSD beacons and PG create messages: https://github.com/ceph/ceph/pull/20517

#21 Updated by Nathan Cutler over 1 year ago

  • Copied to Backport #23077: luminous: mon: ops get stuck in "resend forwarded message to leader" added

#22 Updated by Kefu Chai about 1 year ago

  • Status changed from Pending Backport to Need Review
  • Assignee changed from Greg Farnum to Kefu Chai

#23 Updated by Kefu Chai about 1 year ago

  • Status changed from Need Review to Pending Backport

#24 Updated by Nathan Cutler about 1 year ago

  • Status changed from Pending Backport to Resolved

Also available in: Atom PDF