Ceph » RADOS

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

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)

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.

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

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

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.

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

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

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.

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

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?

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);

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?

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

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.

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

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.