Hi Haomai,
I'm having trouble fixing an issue with AsyncMessenger vs fork with the
new wip-config branch. I'm wondering if you can help?
The thing that has changed is that global_init now sets up a messenger
instance to talk to the monitor, fetch the config and monmap, and then
tears it down again. A side-effect of this is that the singletons for the
EventCenter and Stack in AsyncMessenger are present at the time of the
fork(). And it's not quite behaving as it should. The symptom I'm seeing
is that rbd-nbd is hanging strangely (and somewhat non-deterministically)
when trying to map an image.
wip-sage3-testing-2018-02-28-1744 is the branch I'm working against
currently. It includes wip-config, and fix rbd-nbd to adjust the timing
of the prefork calls, and a patch on top that allows the cct->_log::stop()
to be called if it hasn't been started.
The way things work in this branch, global_init does the temp connection
and tears everything down, except that the singleton Stack and EventCenter
are still there. At fork time, the fork hooks get called for
AsyncMessenger so it does the stop() before and start() after to recreate
the threads. That seems to work.. except I think something is not
quite right because it doesn't reliably talk to the cluster afterwards. I
see exchanges like
gnit:build (wip-nbd-hell) 05:03 PM $ sudo CEPH_ARGS="--debug-ms 1 --debug-rbd 10 --log-to-stderr" bin/rbd-nbd map barr
[sudo] password for sage:
2018-02-28 17:03:59.293 7f06a6b7c880 -1 WARNING: all dangerous and experimental features are enabled.
2018-02-28 17:03:59.296 7f06a6b7c880 1 Processor -- start
2018-02-28 17:03:59.296 7f06a6b7c880 1 -- - start start
2018-02-28 17:03:59.297 7f06a6b7c880 1 -- - --> 127.0.0.1:40023/0 -- auth(proto 0 34 bytes epoch 0) v1 -- 0x56089092b550 con 0
2018-02-28 17:03:59.297 7f0693fff700 1 -- 127.0.0.1:0/1758722310 learned_addr learned my addr 127.0.0.1:0/1758722310
2018-02-28 17:03:59.298 7f0692ffd700 1 -- 127.0.0.1:0/1758722310 <== mon.0 127.0.0.1:40023/0 1 ==== mon_map magic: 0 v1 ==== 175+0+0 (698871189 0 0) 0x7f0684002630 con 0x56089093e730
2018-02-28 17:03:59.298 7f0692ffd700 1 -- 127.0.0.1:0/1758722310 <== mon.0 127.0.0.1:40023/0 2 ==== auth_reply(proto 2 0 (0) Success) v1 ==== 33+0+0 (3411293466 0 0) 0x7f06840029b0 con 0x56089093e730
2018-02-28 17:03:59.298 7f0692ffd700 1 -- 127.0.0.1:0/1758722310 --> 127.0.0.1:40023/0 -- auth(proto 2 32 bytes epoch 0) v1 -- 0x7f06800017c0 con 0
2018-02-28 17:03:59.299 7f0692ffd700 1 -- 127.0.0.1:0/1758722310 <== mon.0 127.0.0.1:40023/0 3 ==== auth_reply(proto 2 0 (0) Success) v1 ==== 206+0+0 (711149518 0 0) 0x7f0684002fb0 con 0x56089093e730
2018-02-28 17:03:59.299 7f0692ffd700 1 -- 127.0.0.1:0/1758722310 --> 127.0.0.1:40023/0 -- mon_subscribe({config=0+,monmap=0+}) v3 -- 0x56089079d2f0 con 0
2018-02-28 17:03:59.300 7f0692ffd700 1 -- 127.0.0.1:0/1758722310 <== mon.0 127.0.0.1:40023/0 4 ==== config(3 keys) v1 ==== 100+0+0 (3814196429 0 0) 0x5608908cd1e0 con 0x56089093e730
2018-02-28 17:03:59.300 7f0692ffd700 1 -- 127.0.0.1:0/1758722310 <== mon.0 127.0.0.1:40023/0 5 ==== mon_map magic: 0 v1 ==== 175+0+0 (698871189 0 0) 0x7f0684001390 con 0x56089093e730
2018-02-28 17:03:59.300 7f06a6b7c880 1 -- 127.0.0.1:0/1758722310 >> 127.0.0.1:40023/0 conn(0x56089093e730 :-1 s=STATE_OPEN pgs=62 cs=1 l=1).mark_down
2018-02-28 17:03:59.300 7f06a6b7c880 1 -- 127.0.0.1:0/1758722310 shutdown_connections
2018-02-28 17:03:59.301 7f06a6b7c880 1 -- 127.0.0.1:0/1758722310 shutdown_connections
2018-02-28 17:03:59.301 7f06a6b7c880 1 -- 127.0.0.1:0/1758722310 wait complete.
2018-02-28 17:03:59.301 7f06a6b7c880 1 -- 127.0.0.1:0/1758722310 >> 127.0.0.1:0/1758722310 conn(0x560890927300 :-1 s=STATE_NONE pgs=0 cs=0 l=0).mark_down
(^ the initial pre-fork exchange to get the config)
2018-02-28 17:03:59.302 7f06a6b7c880 -1 WARNING: all dangerous and experimental features are enabled.
2018-02-28 17:03:59.302 7f06a6b7c880 0 ceph version 13.0.1-2356-g3f9027014b (3f9027014ba1fa805ab596155d6f4b599ab00806) mimic (dev), process (unknown), pid 15464
2018-02-28 17:03:59.303 7f06a6b7c880 0 pidfile_write: ignore empty --pid-file
2018-02-28 17:03:59.303 7f06a6b7c880 0 pidfile_write: ignore empty --pid-file
2018-02-28 17:03:59.307 7f06a6b7c880 -1 WARNING: all dangerous and experimental features are enabled.
2018-02-28 17:03:59.309 7f06a6b7c880 1 Processor -- start
2018-02-28 17:03:59.309 7f06a6b7c880 1 -- - start start
2018-02-28 17:03:59.310 7f06a6b7c880 1 -- - --> 127.0.0.1:40023/0 -- auth(proto 0 34 bytes epoch 0) v1 -- 0x560890868100 con 0
2018-02-28 17:03:59.310 7f0693fff700 1 -- 127.0.0.1:0/4125566264 learned_addr learned my addr 127.0.0.1:0/4125566264
2018-02-28 17:03:59.311 7f0691ffb700 1 -- 127.0.0.1:0/4125566264 <== mon.0 127.0.0.1:40023/0 1 ==== mon_map magic: 0 v1 ==== 175+0+0 (698871189 0 0) 0x7f0678002490 con 0x560890868670
2018-02-28 17:03:59.311 7f0691ffb700 1 -- 127.0.0.1:0/4125566264 <== mon.0 127.0.0.1:40023/0 2 ==== auth_reply(proto 2 0 (0) Success) v1 ==== 33+0+0 (2983701339 0 0) 0x7f0678002810 con 0x560890868670
2018-02-28 17:03:59.311 7f0691ffb700 1 -- 127.0.0.1:0/4125566264 --> 127.0.0.1:40023/0 -- auth(proto 2 32 bytes epoch 0) v1 -- 0x7f068c001980 con 0
2018-02-28 17:03:59.312 7f0691ffb700 1 -- 127.0.0.1:0/4125566264 <== mon.0 127.0.0.1:40023/0 3 ==== auth_reply(proto 2 0 (0) Success) v1 ==== 206+0+0 (3905746370 0 0) 0x7f0678002d40 con 0x560890868670
2018-02-28 17:03:59.312 7f0691ffb700 1 -- 127.0.0.1:0/4125566264 --> 127.0.0.1:40023/0 -- mon_subscribe({config=0+,monmap=0+}) v3 -- 0x5608907f6750 con 0
2018-02-28 17:04:02.313 7f06a6b7c880 -1 monclient: get_monmap_and_config failed to get config
2018-02-28 17:04:02.313 7f06a6b7c880 1 -- 127.0.0.1:0/4125566264 >> 127.0.0.1:40023/0 conn(0x560890868670 :-1 s=STATE_OPEN pgs=63 cs=1 l=1).mark_down
2018-02-28 17:04:02.314 7f06a6b7c880 1 -- 127.0.0.1:0/4125566264 --> 127.0.0.1:40023/0 -- auth(proto 0 34 bytes epoch 1) v1 -- 0x56089086c1a0 con 0
2018-02-28 17:09:02.314 7f06a6b7c880 0 monclient(hunting): authenticate timed out after 300
2018-02-28 17:09:02.314 7f06a6b7c880 1 -- 127.0.0.1:0/4125566264 >> 127.0.0.1:40023/0 conn(0x56089086c400 :-1 s=STATE_CONNECTING_WAIT_BANNER_AND_IDENTIFY pgs=0 cs=0 l=0).mark_down
2018-02-28 17:09:02.315 7f06a6b7c880 1 -- 127.0.0.1:0/4125566264 --> 127.0.0.1:40023/0 -- auth(proto 0 34 bytes epoch 1) v1 -- 0x56089086c1a0 con 0
2018-02-28 17:09:02.315 7f06a6b7c880 1 -- 127.0.0.1:0/4125566264 >> 127.0.0.1:40023/0 conn(0x56089086c400 :-1 s=STATE_CONNECTING pgs=0 cs=0 l=0).mark_down
2018-02-28 17:09:02.316 7f06a6b7c880 1 -- 127.0.0.1:0/4125566264 --> 127.0.0.1:40023/0 -- auth(proto 0 34 bytes epoch 1) v1 -- 0x56089086c1a0 con 0
2018-02-28 17:09:02.316 7f06a6b7c880 1 -- 127.0.0.1:0/4125566264 >> 127.0.0.1:40023/0 conn(0x56089086c400 :-1 s=STATE_CONNECTING pgs=0 cs=0 l=0).mark_down
2018-02-28 17:09:02.317 7f06a6b7c880 1 -- 127.0.0.1:0/4125566264 --> 127.0.0.1:40023/0 -- auth(proto 0 34 bytes epoch 1) v1 -- 0x56089086c1a0 con 0
2018-02-28 17:09:02.317 7f06a6b7c880 1 -- 127.0.0.1:0/4125566264 >> 127.0.0.1:40023/0 conn(0x56089086c400 :-1 s=STATE_CONNECTING pgs=0 cs=0 l=0).mark_down
2018-02-28 17:09:02.318 7f06a6b7c880 1 -- 127.0.0.1:0/4125566264 --> 127.0.0.1:40023/0 -- auth(proto 0 34 bytes epoch 1) v1 -- 0x56089086c1a0 con 0
2018-02-28 17:09:02.318 7f06a6b7c880 1 -- 127.0.0.1:0/4125566264 >> 127.0.0.1:40023/0 conn(0x56089086c400 :-1 s=STATE_CONNECTING pgs=0 cs=0 l=0).mark_down
2018-02-28 17:09:02.319 7f06a6b7c880 1 -- 127.0.0.1:0/4125566264 --> 127.0.0.1:40023/0 -- auth(proto 0 34 bytes epoch 1) v1 -- 0x56089086c1a0 con 0
2018-02-28 17:09:02.319 7f06a6b7c880 1 -- 127.0.0.1:0/4125566264 >> 127.0.0.1:40023/0 conn(0x56089086c400 :-1 s=STATE_CONNECTING pgs=0 cs=0 l=0).mark_down
2018-02-28 17:09:02.320 7f06a6b7c880 1 -- 127.0.0.1:0/4125566264 --> 127.0.0.1:40023/0 -- auth(proto 0 34 bytes epoch 1) v1 -- 0x56089086c1a0 con 0
2018-02-28 17:09:02.320 7f06a6b7c880 1 -- 127.0.0.1:0/4125566264 >> 127.0.0.1:40023/0 conn(0x56089086c400 :-1 s=STATE_CONNECTING pgs=0 cs=0 l=0).mark_down
2018-02-28 17:09:02.321 7f06a6b7c880 1 -- 127.0.0.1:0/4125566264 --> 127.0.0.1:40023/0 -- auth(proto 0 34 bytes epoch 1) v1 -- 0x56089086c1a0 con 0
2018-02-28 17:09:02.321 7f06a6b7c880 1 -- 127.0.0.1:0/4125566264 >> 127.0.0.1:40023/0 conn(0x56089086c400 :-1 s=STATE_CONNECTING pgs=0 cs=0 l=0).mark_down
2018-02-28 17:09:02.322 7f06a6b7c880 1 -- 127.0.0.1:0/4125566264 --> 127.0.0.1:40023/0 -- auth(proto 0 34 bytes epoch 1) v1 -- 0x56089086c1a0 con 0
2018-02-28 17:09:02.322 7f06a6b7c880 1 -- 127.0.0.1:0/4125566264 >> 127.0.0.1:40023/0 conn(0x56089086c400 :-1 s=STATE_CONNECTING pgs=0 cs=0 l=0).mark_down
2018-02-28 17:09:02.322 7f06a6b7c880 1 -- 127.0.0.1:0/4125566264 shutdown_connections
2018-02-28 17:09:29.499 7f06a6b7c880 1 -- 127.0.0.1:0/4125566264 shutdown_connections
2018-02-28 17:09:29.499 7f06a6b7c880 1 -- 127.0.0.1:0/4125566264 wait complete.
2018-02-28 17:09:29.499 7f06a6b7c880 1 -- 127.0.0.1:0/4125566264 >> 127.0.0.1:0/4125566264 conn(0x560890863d80 :-1 s=STATE_NONE pgs=0 cs=0 l=0).mark_down
rbd-nbd: failed to map, status: (110) Connection timed out
Notice we get a few messages back but the all of them; the mon
log indicates it never got the subscribe message. Other times I run it I
get *no* successful interaction with the mon.
My guess would be some stop/start issue with the singletons. What
confuses me is that this behavior similarish to what the OSD is doing
(creating a messenger before the fork, forking, and then using it) but it
doesn't seem to have any problems.
Any ideas? It's easy to reproduce with that branch and
bin/init-ceph stop ; MON=1 OSD=1 MDS=0 ../src/vstart.sh -d -n -x -l
bin/ceph osd pool create rbd 1
sudo CEPH_ARGS="--debug-ms 1 --log-to-stderr" bin/rbd-nbd map doesnotexist
sage
--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
