Mismatching nonce for 'ceph osd.0 tell'

Commit Message

Willem Jan Withagen Dec. 13, 2016, 1:34 a.m. UTC

On 13-12-2016 02:02, Willem Jan Withagen wrote:
> On 10-12-2016 01:39, Willem Jan Withagen wrote:
>> On 9-12-2016 13:02, Willem Jan Withagen wrote:
>>> On 9-12-2016 10:22, Willem Jan Withagen wrote:
>>>> On 9-12-2016 09:59, kefu chai wrote:
>>>>> On Thu, Dec 8, 2016 at 8:30 PM, Willem Jan Withagen <[e-mail]> wrote:
>>>>>> On 8-12-2016 11:03, kefu chai wrote:
>>>>>>> On Tue, Oct 4, 2016 at 7:57 PM, Willem Jan Withagen <[e-mail]> wrote:
>>>>>>>> On 3-10-2016 19:50, Gregory Farnum wrote:
>>>>>>>>>> Question here is:
>>>>>>>>>>   If I ask 'ceph osd dump', I'm actually asking ceph-mon.
>>>>>>>>>>   And cehp-mon has learned this from (crush?)maps being sent to it by
>>>>>>>>>>   ceph-osd.
>>>>>>>>> The monitor has learned about specific IP addresses/nonces/etc via
>>>>>>>>> MOSDBoot messages from the OSDs. The crush locations are set via
>>>>>>>>> monitor command messages, generally invoked as part of the init
>>>>>>>>> scripts. Maps are generated entirely on the monitor. :)
>>>>>>>>>
>>>>>>>>>> Is there an easy way to debug/monitor the content of what ceph-osd sends
>>>>>>>>>> and ceph-mon receives in the maps?
>>>>>>>>>> Just to make sure that it is clear where the problem occurs.
>>>>>>>>> You should be able to see the info going in and out by bumping the
>>>>>>>>> debug levels up — every message's "print" function is invoked when
>>>>>>>>> it's sent/received as long as you have "debug ms = 1". It looks like
>>>>>>>>> the MOSDBoot message doesn't natively dump its addresses but you can
>>>>>>>>> add them easily if you need to.
>>>>>>>> Hi Greg,
>>>>>>>>
>>>>>>>> Thanx for the answer....
>>>>>>>>
>>>>>>>> I've got debug_ms already pumped up all the way to 20.
>>>>>>>> So I do get to see what addresses are selected during bind. But still
>>>>>>>> they do not end up at the MON, and 'ceph osd dump' reports:
>>>>>>>>         :/0
>>>>>>>> as bind address.
>>>>>>>>
>>>>>>>> I'm going to add some more debugs to actually see what MOSDBoot is doing....
>>>>>>> there are multiple messengers used by ceph-osd, the one connected by
>>>>>>> rados client is the external/public messenger. it is also used by osd
>>>>>>> to talk with the monitor.
>>>>>>>
>>>>>>> the nonce of the external address of an OSD does not change after it's
>>>>>>> up: it's always the pid of ceph-osd process. and the (peer) address of
>>>>>>> the booting OSD collected by monitor comes from the connection's
>>>>>>> peer_addr field, which is set when the monitor accepts the connection
>>>>>>> from OSD. see STATE_ACCEPTING_WAIT_BANNER_ADDR case block in
>>>>>>> AsyncConnection::_process_connection().
>>>>>>>
>>>>>>> but there are chances that an OSD is restarted and fail to bind its
>>>>>>> external messenger to the specified the port. in that case, ceph-osd
>>>>>>> will try with another port, but keep the nonce the same. but when it
>>>>>>> comes to other messengers used by ceph-osd, their nonces increase by
>>>>>>> 1000000 every time they rebind. that's why "ceph osd thrash" can
>>>>>>> change the nonces of the cluster_addr, heartbeat_back_addr and
>>>>>>> heartbeat_front_addr. the PR of
>>>>>>> https://github.com/ceph/ceph/pull/11706 actually changes the behavior
>>>>>>> of the messengers of these three messengers. and it has nothing to do
>>>>>>> with the external messenger to which the ceph cli client is
>>>>>>> connecting.
>>>>>>>
>>>>>>> so you might want to check
>>>>>>> 1) how/why the nonce of the messenger in MonClient is 1000000 + $pid
>>>>>>> 2) while the nonce of the same messenger is $pid when the ceph cli
>>>>>>> connects to it.
>>>>>>>
>>>>>>> my PR of https://github.com/ceph/ceph/pull/11804 is more of a cleanup.
>>>>>>> it avoids setting the nonce before the rebind finishes. and i tried
>>>>>>> with your producer on my linux box, no luck =(
>>>>>> Right,
>>>>>>
>>>>>> You gave me a lot of things to think about, and to start figuring out.
>>>>>>
>>>>>> And you are right that something really bad needs to happen to an OSD to
>>>>>> get in this state. But that is what the tests actually do: They just
>>>>>> down/up or kill OSDs and restart.
>>>>>>
>>>>>> And from previous discussions I "learned" that if the process doesn't
>>>>>> die but needs to rebind on the port, the OSD stays at the same port but
>>>>>> increments the nonce to indicate that it is a fresh connection. And log
>>>>> the external messenger should *not* increment its nonce.
>>>>>
>>>>>> printing actually shows that the code is going thru a rebind.
>>>>> and it should *not* go through rebind().
>>>> I have to dig thru the testscript but as far as I can tell just about
>>>> all of the daemons are getting reboots in this test.
>>>>
>>>> So when would I get a rebind?
>>>>
>>>> I thought it was because I had an OSD incorrectly marked down:
>>>> ./src/osd/OSD.cc:7074:                 << " wrongly marked me down";
>>>> This I found in the logs, and then I got a rebind.
>>>>
>>>> Wido suggested looking for this message, on my question why my OSDs were
>>>> not getting UP after a good hustle with all OSDs and MONs.
>>>>
>>>> And that is one of the tests in cephtool-test-mon.sh.
>>>> right before the 'ceph tell osd.0 version' there are tests like:
>>>>   ceph osd set noup
>>>>   ceph osd down 0
>>>>   ceph osd dump | grep 'osd.0 down'
>>>>   ceph osd unset noup
>>>> and
>>>>   ceph osd reweight osd.0 .5
>>>>   ceph osd dump | grep ^osd.0 | grep 'weight 0.5'
>>>>   ceph osd out 0
>>>>   ceph osd in 0
>>>>   ceph osd dump | grep ^osd.0 | grep 'weight 0.5'
>>>>
>>>>
>>>>>> Now the bad thing is that the Linux and FreeBSD log do comparable things
>>>>>> with my (small) change to the setting of addr. And the nonce is indeed
>>>>>> incremented, which increment is actually picked up by all ceph components.
>>>> So now I have 2 challenges??
>>>>
>>>> 1) Find out why I get a rebind, where you think I should not.
>>>>    For that I'll have to collect all maltreatment that is done in
>>>>    cephtool-test-mon.sh. And again compare the Linux and FreeBSD logs
>>>>    to see what is up.
>>>> 2) If we get a rebind...
>>>>    Why doesn't the FreeBSD version end up with consistent noncees.
>>>>
>>>> "Good thing" about the previous code was that I could tweak it, and at
>>>> least get it to Work for FreeBSD. Have not had the time to see if I
>>>> could again with this code....
>>> So the smallest sequence I can find that demonstrates the problem:
>>> function test_mon_rebind()
>>> {
>>>   ceph osd set noup
>>>   ceph osd down 0
>>>   ceph osd dump | grep 'osd.0 down'
>>>   ceph osd unset noup
>>>   max_run=1000
>>>   for ((i=0; i < $max_run; i++)); do
>>>     if ! ceph osd dump | grep 'osd.0 up'; then
>>>       echo "waiting for osd.0 to come back up ($i/$max_run)"
>>>       sleep 1
>>>     else
>>>       break
>>>     fi
>>>   done
>>>   ceph osd dump | grep 'osd.0 up'
>>>
>>>   for id in `ceph osd ls` ; do
>>>     retry_eagain 5 map_enxio_to_eagain ceph tell osd.$id version
>>>   done
>>> }
>>>
>>> Which matches with what I thought I knew:
>>>   OSD down => up => rebind
>>> which follows from the log where the osd complains about being marked
>>> down incorrectly.
>>> search for
>>>    log_channel(cluster) log [WRN] : map e8 wrongly marked me down
>>> in the osd.0.log
>>>
>>
>> I ran the code snippet, and it DOES generate a rebind even on Linux
>> Centos 7.
>> So I expect that the rebind action is called for?
>>
>> Also note that at least one nonce is incremented, AND new ports are
>> selected.
>> 6801,6802,6803 are avoided, and it looks like already connected ports
>> are avoided as well.
>> (obvious, since binding on them will not work)
>>
>> Next is the FreeBSD log, and that one is relatively seriously wrong
>> since nonce are 0 .
>> And that must be incorrect.
>>
>> Last is the log of the current master code with the patch I made of
>> msg->my_addr, versus addr.
>> IMHO a change that should be semantical equal?
>>   return bind(msgr->my_inst.addr, new_avoid);
>>   // return bind(addr, new_avoid);
>> One thing that is not working there is the port avoidance. That I have
>> to look into since there is no reason
>> why this should not work under FreeBSD.
> 
> I have tested with the new code Kefu submitted to master this afternoon:
> The Linux variant gives:
> 7f36b1dd1700  1 -- 127.0.0.1:6800/13799 <== mon.2 127.0.0.1:8204/0 38
> ==== osd_map(18..21 src has 1..21) v3 ==== 1012+0+0 (424389225 0 0)
> 0x7f36cdcc7cc0 con 0x7f36cdb24000
> 7f36b5ac6700  0 log_channel(cluster) log [WRN] : map e21 wrongly marked
> me down
> 7f36b5ac6700  1 -- 127.0.0.1:6801/13799 rebind rebind avoid 6801,6802,6803
> 7f36b5ac6700  1 -- 127.0.0.1:6801/13799 shutdown_connections
> 7f36b5ac6700  1 -- 127.0.0.1:6812/1013799 _finish_bind bind my_inst.addr
> is 127.0.0.1:6812/1013799
> 7f36b5ac6700  1  Processor -- start
> 
> Note that the new allocated channel is on port 6812 with an incremented
> nonce, and the channel on port 6800 is not touched. Probably because it
> is still open, and it is not the channel being rebound.
> 
> Now the FreeBSD version:
> bb99f80  1 -- 127.0.0.1:6800/6449 <== mon.1 127.0.0.1:7203/0 158 ====
> osd_map(172..175 src has 1..175) v3 ==== 1045+0+0 (1598708051 0 0)
> 0xc08eb40 con 0xbbca000
> bb98d80  0 log_channel(cluster) log [WRN] : map e175 wrongly marked me down
> bb98d80  1 -- 127.0.0.1:6801/6449 rebind rebind avoid 6801,6802,6803
> bb98d80  1 -- 127.0.0.1:6801/6449 shutdown_connections
> bb98d80  1 -- 127.0.0.1:6800/1006449 _finish_bind bind my_inst.addr is
> 127.0.0.1:6800/1006449
> bb98d80  1  Processor -- start
> 
> And here the new channel is allocated on port 6800, as if that would be
> available. Should it also not be marked as such in avoid_ports??
> But that port is still being used as is indicated in the first line.
> FreeBSD does not seem to have a problem binding to that port ??
> And thus a channel is listening on 6800, but with a new nonce.
> So that could be the reason that ceph and rados are complaining that
> they cannot talk to osd.0
> 
> So why is 6800 not in the list for channels to avoid?

I patched osd/OSD.cc: (added to fit with 80 chars)
 avoid_ports.insert(hb_front_server_messenger->get_myaddr().get_port());

And just adding this extra port to avoid gets things done.

I guess that there are enough remarks to be made on this patch??

--WjW

--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
the body of a message to [e-mail]
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Patch

--- a/src/osd/OSD.cc
+++ b/src/osd/OSD.cc
@@ -7126,6 +7126,7 @@  void OSD::_committed_osd_maps(epoch_t first,
epoch_t last, MOSDMap *m)
        start_waiting_for_healthy();

        set<int> avoid_ports;
+        avoid_ports.insert(client_messenger->get_myaddr().get_port());
        avoid_ports.insert(cluster_messenger->get_myaddr().get_port());
 avoid_ports.insert(hb_back_server_messenger->get_myaddr().get_port());