Bug #5804
closedmon: binds to 0.0.0.0:6800something port
Added by Sage Weil almost 11 years ago. Updated about 10 years ago.
0%
Description
it keeps binding to 0.0.0.0:6801 instead of the mon addr.. why?
Files
| ceph-mon.frank.log (325 KB) ceph-mon.frank.log | Alexandre Marangone, 02/04/2014 12:27 PM |
Updated by Joao Eduardo Luis almost 11 years ago
Is the monitor being specified in 'mon initial members'?
Updated by Joao Eduardo Luis almost 11 years ago
Just saw it is; my connection to that machine is however painfully slow. Will update as soon as I figure something else.
Updated by Joao Eduardo Luis almost 11 years ago
ubuntu@mira117:~$ monmaptool --print mira117.monmap monmaptool: monmap file mira117.monmap epoch 2 fsid 296ea68b-9bc4-4395-91f7-69d75b5099f4 last_changed 2013-07-10 17:55:08.626740 created 0.000000 0: 10.214.136.106:6789/0 mon.mira107 1: 10.214.136.108:6789/0 mon.mira106 2: 10.214.136.114:6789/0 mon.mira103 3: 10.214.137.128:6789/0 mon.mira115 4: 0.0.0.0:6801/0 mon.mira117
Looking into how
Updated by Joao Eduardo Luis over 10 years ago
Just noticed that the port is set as 6801 -- that's used by the osds iirc -- and we've seen reports of the messenger grabbing a 6800+ port at times.
Edit: well, duh. That was already on the original bug report.
Updated by Sage Weil over 10 years ago
- Subject changed from mon: mira117 having trouble using it's ip address to mon: binds to 0.0.0.0:6800something port
Updated by Joao Eduardo Luis over 10 years ago
- Status changed from New to Can't reproduce
Have inspected the code and haven't found a reason for this to happen yet, nor was I able to reproduce this at all.
Despite the multiple reports we've been having lately on the lists, until we have some way to reproduce this or we stumble upon it's root cause, I'm closing this.
Updated by Dan Mick over 10 years ago
- Status changed from Can't reproduce to Need More Info
- Priority changed from High to Normal
I did see this again on the mira045 etc. cluster, as I chatted with Joao about, and apparently mattt on IRC is experiencing it today. I can't find anywhere that the mon sets anything other than 6789 or "the specified port" easily; when I was in this state I did a little debugging, and found that by the time I was looking, the monmap indeed had recorded that port number for the monitor (i.e. it wasn't an unassigned variable in the monitor bootup) but I didn't divine how it had happened. I ended up manually correcting the monitor map.
I think perhaps a problem is that by the time you notice, the event is past. I wonder if we have proper logging for this, and if we maybe want to make it on by default, and/or insert a trap to check for this situation, which seems like it must spring from
someone calling Messenger::bind() with an ip but no port. Maybe g_conf->public_addr is getting corrupted somehow so that it has a nonzero port value. Perhaps we could add at least a log message to
if (!g_conf->public_addr.is_blank_ip()) {
ipaddr = g_conf->public_addr;
if (ipaddr.get_port() == 0)
ipaddr.set_port(CEPH_MON_PORT);
Updated by Wido den Hollander over 10 years ago
I saw this happening multiple times during a training class.
During the CEPH 100 training we use the machine "daisy", "eric" and "frank". Initially the monitor "frank" would bind on the correct address, but after a reboot it binds on 0.0.0.0:6800.
You might want to contact JC and ask him for the VirtualBox images. Deploying with ceph-deploy from "daisy" will get you into this situation.
Updated by Alexandre Marangone about 10 years ago
I'm able to reproduce this fairly consistently on the Ceph VM Wido is mentioning.
Any information/debug settings that could help? I can also provide a SSH access if needed.
Updated by Dan Mick about 10 years ago
really think that log message would go a long way toward helping.
Updated by Alexandre Marangone about 10 years ago
- File ceph-mon.frank.log ceph-mon.frank.log added
12:08 <@sage> alram joao wido: on issue 5804 i'm guessing ssh access and debugging is the trick,
although debug ms = 20 debug mon = 20 might be enough
Logs from "ceph-mon -i frank --cluster=ceph --debug-ms 20 --debug-mon 20" attached. SSH access is setup, I'll send the infos in a pm.
Updated by Eric Eastman about 10 years ago
Hi,
I am seeing the same issue on my clusters with 3 monitors. I am running:
ceph --version
ceph version 0.72.2 (a913ded2ff138aefb8cb84d347d72164099cfd60)
cat /proc/version
Linux version 3.12.1-031201-generic (apw@gomeisa) (gcc version 4.6.3 (Ubuntu/Linaro 4.6.3-1ubuntu5) ) #201311201654 SMP Wed Nov 20 21:54:49 UTC 2013
Earlier today the log file showed the address of one of my monitors as:
grep 10.15.2.13:67 /var/log/ceph/ceph-mon.tca13.log.1
2014-02-06 12:32:59.402073 7fc8cb240700 0 -- 10.15.2.13:6789/0 >> 10.15.2.11:6789/0 pipe(0x1c89900 sd=12 :35960 s=2 pgs=40 cs=1 l=0 c=0x1c2cc00).fault with nothing to send, going to standby
Everything was working and the cluster was healthy. I added the line:
osd_pool_default_flag_hashpspool = 1 #better PG layoutto my /etc/ceph/ceph.conf file on all cluster nodes, and then did a:
restart ceph-allon the 3 monitors.
After restarting the monitor, my monitor that was reporting as 10.15.2.13:6789 is now reporting:
tca13=0.0.0.0:6800/0
The other 2 monitors are still reporting their correct address:
monmap e2: 3 mons at {tca11=10.15.2.11:6789/0,tca12=10.15.2.12:6789/0,tca13=0.0.0.0:6800/0}, election epoch 126, quorum 0,1 tca11,tca12
I have rebooted tca13 multiple times, and it still comes up with the address: tca13=0.0.0.0:6800/0
Setting debug mon 20, debug ms 20 in ceph.conf and restarting the monitor, the top of the log file shows:
head \-25 /var/log/ceph/ceph-mon.tca13.log
2014-02-06 14:21:23.703876 7fd603bff7c0 0 ceph version 0.72.2 (a913ded2ff138aefb8cb84d347d72164099cfd60), process ceph-mon, pid 11173
2014-02-06 14:21:23.732703 7fd603bff7c0 10 obtain_monmap
2014-02-06 14:21:23.732801 7fd603bff7c0 10 obtain_monmap read last committed monmap ver 2
2014-02-06 14:21:23.732959 7fd603bff7c0 10 -- :/0 rank.bind 0.0.0.0:6800/0
2014-02-06 14:21:23.733028 7fd603bff7c0 10 accepter.accepter.bind
2014-02-06 14:21:23.733085 7fd603bff7c0 10 accepter.accepter.bind bound to 0.0.0.0:6800/0
2014-02-06 14:21:23.733134 7fd603bff7c0 1 -- 0.0.0.0:6800/0 learned my addr 0.0.0.0:6800/0
2014-02-06 14:21:23.733164 7fd603bff7c0 1 accepter.accepter.bind my_inst.addr is 0.0.0.0:6800/0 need_addr=0
2014-02-06 14:21:23.733361 7fd603bff7c0 1 mon.tca13@-1(probing) e2 preinit fsid c557fdf6-3a52-4095-897f-3601afed6f6e
2014-02-06 14:21:23.733445 7fd603bff7c0 10 mon.tca13@-1(probing) e2 check_fsid cluster_uuid contains 'c557fdf6-3a52-4095-897f-3601afed6f6e'
2014-02-06 14:21:23.733503 7fd603bff7c0 10 mon.tca13@-1(probing) e2 features compat={},rocompat={},incompat={1=initial feature set (~v.18),3=single paxos with k/v store (v0.?)}
2014-02-06 14:21:23.733552 7fd603bff7c0 10 mon.tca13@-1(probing) e2 has_ever_joined = 1
2014-02-06 14:21:23.733633 7fd603bff7c0 10 mon.tca13@-1(probing) e2 sync_last_committed_floor 0
2014-02-06 14:21:23.733661 7fd603bff7c0 10 mon.tca13@-1(probing) e2 init_paxos
2014-02-06 14:21:23.733844 7fd603bff7c0 10 mon.tca13@-1(probing) e2 refresh_from_paxos
2014-02-06 14:21:23.733954 7fd603bff7c0 1 mon.tca13@-1(probing).paxosservice(pgmap 1362262..1362987) refresh upgraded, format 0 -> 1
2014-02-06 14:21:23.733989 7fd603bff7c0 1 mon.tca13@-1(probing).pg v0 on_upgrade discarding in-core PGMap
2014-02-06 14:21:23.734061 7fd603bff7c0 10 mon.tca13@-1(probing).pg v0 update_from_paxos v0, read_full
2014-02-06 14:21:23.734092 7fd603bff7c0 10 mon.tca13@-1(probing).pg v0 read_pgmap_meta
2014-02-06 14:21:23.734280 7fd603bff7c0 20 mon.tca13@-1(probing).pg v1362987 got 0.0
2014-02-06 14:21:23.734320 7fd603bff7c0 20 mon.tca13@-1(probing).pg v1362987 got 0.1
2014-02-06 14:21:23.734357 7fd603bff7c0 20 mon.tca13@-1(probing).pg v1362987 got 0.10
2014-02-06 14:21:23.734394 7fd603bff7c0 20 mon.tca13@-1(probing).pg v1362987 got 0.11
2014-02-06 14:21:23.734427 7fd603bff7c0 20 mon.tca13@-1(probing).pg v1362987 got 0.12
2014-02-06 14:21:23.734461 7fd603bff7c0 20 mon.tca13@-1(probing).pg v1362987 got 0.13
I can attach the whole log if you need it.
Eric Eastman
Updated by Eric Eastman about 10 years ago
To do additional debugging on this problem, I printed out my monmap with:
ceph mon getmap -o zzzz
got latest monmap
monmaptool --print zzzz
monmaptool: monmap file zzzz
epoch 2
fsid c557fdf6-3a52-4095-897f-3601afed6f6e
last_changed 2014-02-06 12:35:58.362966
created 0.000000
0: 10.15.2.11:6789/0 mon.tca11
1: 10.15.2.12:6789/0 mon.tca12
2: 0.0.0.0:6800/0 mon.tca13
After looking at the code in ceph-0.72.2/src/ceph_mon.cc at line 427, it looks like the monitor address is always taken from the monmap, if it is available:
if (monmap.contains(g_conf->name.get_id())) {
ipaddr = monmap.get_addr(g_conf->name.get_id());In my case, restarting the monitor tca13, on 10.15.2.13 with "restart ceph-all" seems to have caused the address:port to change to 0.0.0.0:6800. I feel the problem was caused by the socket call which failed to re-use the existing address:port value, so it went to the next available port, 6800, and used 0.0.0.0 for the address. Once the address is bound to 0.0.0.0:6800, it updated the monmap, so this address is forever stuck on this monitor. I had to delete and recreate the monitor to fix the problem.
I am thinking that logic should be added to the code so if is sees a monmap address of 0.0.0.0, it should output a warning to the log file, change it to the public address at port 6789, and update the monmap, unless there is an overriding entry in the ceph.conf file.
Updated by Joao Eduardo Luis about 10 years ago
- Status changed from Need More Info to In Progress
The 0.0.0.0 portion of the address is normal. Unless a monitor has a prebuilt monmap supplied at time of creation, all addresses will be filed as 0.0.0.0 until the monitor is able to successfully discover the remaining monitors (as specified by 'mon host' in ceph.conf). The real issue here is figuring out how the monitor manages to bind to port 6800.
Updated by Joao Eduardo Luis about 10 years ago
Not wanting to commit to a full diagnosis just yet, this is looking a lot like a mild case of #7212 with a weird result of having the monitor committing a monmap in which it is marked as being 0.0.0.0:0 to disk, which results in the Accepter assigning it a random port on bind.
Now, the port part is orthogonal to the issue. I'm more interested in making sure this is #7212 and is not reproducible on latest, and in finding out why the mon is zeroed out in the monmap when the logs clearly show the leader knowing about it.
Also, although this is (somewhat) easily reproducible with the vms, I haven't been able to concoct a test to reproduce it. Except for the 6800 port thing, which is easily done by modifying the monmaptool to allow adding a monitor with a 0.0.0.0:0 address and have that monmap injected into a monitor.
Updated by Joao Eduardo Luis about 10 years ago
- Status changed from In Progress to Resolved
My suspicions were right, at least as far as the VMs are concerned. Whereas using 0.67.2 or 0.72.2 would hit this every single time on one of the VMs, upgrading ceph to latest dumpling, emperor or master would just have the issues to go away.
The only variation between what was happening in the VMs and the original #7212 is that in this case one of the mons would rewrite its own monmap during recovery, consigning its address to oblivion. This would be triggered because the first two monitors forming quorum would race between committing a monmap v1 to disk and then finding out about the third monitor and allowing it to join the quorum. However, the new monitor would have to recover to join the quorum, would get the v1 monmap, would commit it to disk and proceed to join the quorum. Upon restart of any of the monitors, the address of that last monitor joining the quorum would be 0.0.0.0:0 (as committed to disk before), and one of two cases would happen: #7212 if the monitor being restarted happened to be one of the two initial participants in the quorum, or this ticket if the mon being restarted happened to be the one with a blank ip:port on the monmap.
Patches for #7212 fixed all these issues by making sure the first initial monitos agree on a monmap v1 via a paxos proposal.
Updated by Joao Eduardo Luis about 10 years ago
Also, for those who are ailed by this bug, best solution for them is to remove the affected monitor from the cluster and adding a new one via 'ceph mon add'.