Subtask #2643
closed
Feature #2611: mon: Single-Paxos
mon: Single-Paxos: mds: Strange message behavior on peon
Added by Joao Eduardo Luis almost 12 years ago.
Updated about 11 years ago.
Description
Just for future reference.
When checking how things were going with the monitors, we noticed that the following snippet was being repeated over and over, non-stop.
2012-06-21 16:17:25.584119 7fffee7fc700 1 -- 127.0.0.1:6791/0 <== mds.? 127.0.0.1:6800/25236 322130 ==== auth(proto 2 2 bytes epoch 0) v1 ==== 32+0+0 (2260890001 0 0) 0x7fffc402bbb0 con 0x7fffdc0015b0
2012-06-21 16:17:25.584126 7fffee7fc700 20 mon.c@2(peon) e1 have connection
2012-06-21 16:17:25.584127 7fffee7fc700 20 mon.c@2(peon) e1 ms_dispatch existing session MonSession: mds.? 127.0.0.1:6800/25236 is open for mds.? 127.0.0.1:6800/25236
2012-06-21 16:17:25.584131 7fffee7fc700 20 mon.c@2(peon) e1 caps
2012-06-21 16:17:25.584132 7fffee7fc700 10 mon.c@2(peon).paxosservice(auth) dispatch auth(proto 2 2 bytes epoch 0) v1 from mds.? 127.0.0.1:6800/25236
2012-06-21 16:17:25.584154 7fffee7fc700 10 mon.c@2(peon).auth v15 update_from_paxos
2012-06-21 16:17:25.584169 7fffee7fc700 10 mon.c@2(peon).auth v15 preprocess_query auth(proto 2 2 bytes epoch 0) v1 from mds.? 127.0.0.1:6800/25236
2012-06-21 16:17:25.584180 7fffee7fc700 10 mon.c@2(peon).auth v15 prep_auth() blob_size=2
2012-06-21 16:17:25.584189 7fffee7fc700 10 cephx server mds.a: handle_request getting rotating secret for mds.a
2012-06-21 16:17:25.584208 7fffee7fc700 1 -- 127.0.0.1:6791/0 --> 127.0.0.1:6800/25236 -- auth_reply(proto 2 0 Success) v1 -- ?+0 0x7fffd53c5a80 con 0x7fffdc0015b0
2012-06-21 16:17:25.584222 7fffee7fc700 1 -- 127.0.0.1:6791/0 <== mds.? 127.0.0.1:6801/25414 298416 ==== auth(proto 2 2 bytes epoch 0) v1 ==== 32+0+0 (2260890001 0 0) 0x7fffcc00e8e0 con 0x7fffdc001090
2012-06-21 16:17:25.584229 7fffee7fc700 20 mon.c@2(peon) e1 have^C connection
2012-06-21 16:17:25.584230 7fffee7fc700 20 mon.c@2(peon) e1 ms_dispatch existing session MonSession: mds.? 127.0.0.1:6801/25414 is open for mds.? 127.0.0.1:6801/25414
2012-06-21 16:17:25.584234 7fffee7fc700 20 mon.c@2(peon) e1 caps
2012-06-21 16:17:25.584235 7fffee7fc700 10 mon.c@2(peon).paxosservice(auth) dispatch auth(proto 2 2 bytes epoch 0) v1 from mds.? 127.0.0.1:6801/25414
2012-06-21 16:17:25.584260 7fffee7fc700 10 mon.c@2(peon).auth v15 update_from_paxos
2012-06-21 16:17:25.584275 7fffee7fc700 10 mon.c@2(peon).auth v15 preprocess_query auth(proto 2 2 bytes epoch 0) v1 from mds.? 127.0.0.1:6801/25414
2012-06-21 16:17:25.584285 7fffee7fc700 10 mon.c@2(peon).auth v15 prep_auth() blob_size=2
2012-06-21 16:17:25.584294 7fffee7fc700 10 cephx server mds.b: handle_request getting rotating secret for mds.b
2012-06-21 16:17:25.584313 7fffee7fc700 1 -- 127.0.0.1:6791/0 --> 127.0.0.1:6801/25414 -- auth_reply(proto 2 0 Success) v1 -- ?+0 0x7fffd53c46c0 con 0x7fffdc001090
2012-06-21 16:17:25.584327 7fffee7fc700 1 -- 127.0.0.1:6791/0 <== mds.? 127.0.0.1:6802/25594 309137 ==== auth(proto 2 2 bytes epoch 0) v1 ==== 32+0+0 (2260890001 0 0) 0x7fffb8023dc0 con 0x7fffdc001ad0
2012-06-21 16:17:25.584334 7fffee7fc700 20 mon.c@2(peon) e1 have connection
2012-06-21 16:17:25.584335 7fffee7fc700 20 mon.c@2(peon) e1 ms_dispatch existing session MonSession: mds.? 127.0.0.1:6802/25594 is open for mds.? 127.0.0.1:6802/25594
2012-06-21 16:17:25.584339 7fffee7fc700 20 mon.c@2(peon) e1 caps
2012-06-21 16:17:25.584340 7fffee7fc700 10 mon.c@2(peon).paxosservice(auth) dispatch auth(proto 2 2 bytes epoch 0) v1 from mds.? 127.0.0.1:6802/25594
2012-06-21 16:17:25.584363 7fffee7fc700 10 mon.c@2(peon).auth v15 update_from_paxos
2012-06-21 16:17:25.584378 7fffee7fc700 10 mon.c@2(peon).auth v15 preprocess_query auth(proto 2 2 bytes epoch 0) v1 from mds.? 127.0.0.1:6802/25594
2012-06-21 16:17:25.584388 7fffee7fc700 10 mon.c@2(peon).auth v15 prep_auth() blob_size=2
2012-06-21 16:17:25.584397 7fffee7fc700 10 cephx server mds.c: handle_request getting rotating secret for mds.c
2012-06-21 16:17:25.584415 7fffee7fc700 1 -- 127.0.0.1:6791/0 --> 127.0.0.1:6802/25594 -- auth_reply(proto 2 0 Success) v1 -- ?+0 0x7fffd53c7010 con 0x7fffdc001ad0
We have no idea what is causing it.
This is what can be seen on the Leader:
2012-06-21 16:25:16.770718 7fffeeffd700 1 -- 127.0.0.1:6789/0 <== mds.? 127.0.0.1:6802/25594 5 ==== mdsbeacon(4409/c up:boot seq 2241 v0) v2 ==== 240+0+0 (1013814919 0 0) 0x7fffc40049d0 con 0x7fffe8001da0
2012-06-21 16:25:16.770742 7fffeeffd700 10 mon.a@0(leader).paxosservice(mdsmap) dispatch mdsbeacon(4409/c up:boot seq 2241 v0) v2 from mds.? 127.0.0.1:6802/25594
2012-06-21 16:25:16.770815 7fffeeffd700 10 mon.a@0(leader).mds e1 preprocess_query mdsbeacon(4409/c up:boot seq 2241 v0) v2 from mds.? 127.0.0.1:6802/25594
2012-06-21 16:25:16.770834 7fffeeffd700 0 mon.a@0(leader).mds e1 preprocess_beason got MMDSBeacon from entity with insufficient privileges
2012-06-21 16:25:16.770841 7fffeeffd700 10 -- 127.0.0.1:6789/0 dispatch_throttle_release 240 to dispatch throttler 240/104857600
2012-06-21 16:25:18.154593 7fffee7fc700 10 mon.a@0(leader).pg v3 check_down_pgs
2012-06-21 16:25:18.154608 7fffee7fc700 10 mon.a@0(leader).pg v3 v3: 24 pgs: 24 creating; 0 bytes data, 0 KB used, 0 KB / 0 KB avail
2012-06-21 16:25:18.154645 7fffee7fc700 10 mon.a@0(leader).mds e1 e1: 0/0/1 up
2012-06-21 16:25:18.154671 7fffee7fc700 10 mon.a@0(leader).osd e2 e2: 1 osds: 0 up, 0 in
2012-06-21 16:25:18.154676 7fffee7fc700 5 mon.a@0(leader).osd e2 can_mark_down current in_ratio 0 < min 0.3, will not mark osds out
2012-06-21 16:25:18.154688 7fffee7fc700 10 mon.a@0(leader).osd e2 tick NOOUT flag set, not checking down osds
2012-06-21 16:25:18.154767 7fffee7fc700 10 mon.a@0(leader).log v29 log
2012-06-21 16:25:18.154807 7fffee7fc700 10 mon.a@0(leader).auth v15 update_from_paxos
2012-06-21 16:25:18.154859 7fffee7fc700 10 mon.a@0(leader).auth v15 auth
2012-06-21 16:25:18.154897 7fffee7fc700 10 cephx keyserver: _check_rotating_secrets
2012-06-21 16:25:18.512384 7fffedefa700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6802/25594 pipe(0x7fffe8001b30 sd=28 pgs=201 cs=1 l=1).reader wants 42 from dispatch throttler 0/104857600
2012-06-21 16:25:18.512427 7fffedefa700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6802/25594 pipe(0x7fffe8001b30 sd=28 pgs=201 cs=1 l=1).aborted = 0
2012-06-21 16:25:18.512450 7fffedefa700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6802/25594 pipe(0x7fffe8001b30 sd=28 pgs=201 cs=1 l=1).reader got message 6 0x7fffc4004f80 mon_subscribe({mdsmap=0+,monmap=2+}) v2
2012-06-21 16:25:18.512540 7ffff43f2700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6802/25594 pipe(0x7fffe8001b30 sd=28 pgs=201 cs=1 l=1).writer: state = 2 policy.server=1
2012-06-21 16:25:18.512569 7ffff43f2700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6802/25594 pipe(0x7fffe8001b30 sd=28 pgs=201 cs=1 l=1).write_ack 6
2012-06-21 16:25:18.512598 7ffff43f2700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6802/25594 pipe(0x7fffe8001b30 sd=28 pgs=201 cs=1 l=1).writer: state = 2 policy.server=1
2012-06-21 16:25:18.512615 7fffeeffd700 1 -- 127.0.0.1:6789/0 <== mds.? 127.0.0.1:6802/25594 6 ==== mon_subscribe({mdsmap=0+,monmap=2+}) v2 ==== 42+0+0 (1735446458 0 0) 0x7fffc4004f80 con 0x7fffe8001da0
2012-06-21 16:25:18.512647 7fffeeffd700 10 mon.a@0(leader) e1 handle_subscribe mon_subscribe({mdsmap=0+,monmap=2+}) v2
2012-06-21 16:25:18.512656 7fffeeffd700 10 mon.a@0(leader) e1 check_sub monmap next 2 have 1
2012-06-21 16:25:18.512661 7fffeeffd700 1 -- 127.0.0.1:6789/0 --> mds.? 127.0.0.1:6802/25594 -- mon_subscribe_ack(300s) v1 -- ?+0 0x7fffd40dd4a0
2012-06-21 16:25:18.512681 7fffeeffd700 10 -- 127.0.0.1:6789/0 dispatch_throttle_release 42 to dispatch throttler 42/104857600
2012-06-21 16:25:18.512718 7ffff43f2700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6802/25594 pipe(0x7fffe8001b30 sd=28 pgs=201 cs=1 l=1).writer: state = 2 policy.server=1
2012-06-21 16:25:18.512814 7ffff43f2700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6802/25594 pipe(0x7fffe8001b30 sd=28 pgs=201 cs=1 l=1).writer: state = 2 policy.server=1
2012-06-21 16:25:18.561005 7ffff42f1700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6800/25236 pipe(0x7fffe8001090 sd=27 pgs=216 cs=1 l=1).reader wants 42 from dispatch throttler 0/104857600
2012-06-21 16:25:18.561053 7ffff42f1700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6800/25236 pipe(0x7fffe8001090 sd=27 pgs=216 cs=1 l=1).aborted = 0
2012-06-21 16:25:18.561083 7ffff42f1700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6800/25236 pipe(0x7fffe8001090 sd=27 pgs=216 cs=1 l=1).reader got message 6 0x7fffd0002ce0 mon_subscribe({mdsmap=0+,monmap=2+}) v2
2012-06-21 16:25:18.561206 7fffedcf9700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6800/25236 pipe(0x7fffe8001090 sd=27 pgs=216 cs=1 l=1).writer: state = 2 policy.server=1
2012-06-21 16:25:18.561247 7fffedcf9700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6800/25236 pipe(0x7fffe8001090 sd=27 pgs=216 cs=1 l=1).write_ack 6
2012-06-21 16:25:18.561201 7fffeeffd700 1 -- 127.0.0.1:6789/0 <== mds.? 127.0.0.1:6800/25236 6 ==== mon_subscribe({mdsmap=0+,monmap=2+}) v2 ==== 42+0+0 (1735446458 0 0) 0x7fffd0002ce0 con 0x7fffe8002050
2012-06-21 16:25:18.561264 7fffeeffd700 10 mon.a@0(leader) e1 handle_subscribe mon_subscribe({mdsmap=0+,monmap=2+}) v2
2012-06-21 16:25:18.561270 7fffedcf9700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6800/25236 pipe(0x7fffe8001090 sd=27 pgs=216 cs=1 l=1).writer: state = 2 policy.server=1
2012-06-21 16:25:18.561276 7fffeeffd700 10 mon.a@0(leader) e1 check_sub monmap next 2 have 1
2012-06-21 16:25:18.561282 7fffeeffd700 1 -- 127.0.0.1:6789/0 --> mds.? 127.0.0.1:6800/25236 -- mon_subscribe_ack(300s) v1 -- ?+0 0x7fffd40dda80
2012-06-21 16:25:18.561307 7fffeeffd700 10 -- 127.0.0.1:6789/0 dispatch_throttle_release 42 to dispatch throttler 42/104857600
2012-06-21 16:25:18.561321 7fffedcf9700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6800/25236 pipe(0x7fffe8001090 sd=27 pgs=216 cs=1 l=1).writer: state = 2 policy.server=1
2012-06-21 16:25:18.561384 7fffedcf9700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6800/25236 pipe(0x7fffe8001090 sd=27 pgs=216 cs=1 l=1).writer: state = 2 policy.server=1
2012-06-21 16:25:18.826526 7ffff42f1700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6800/25236 pipe(0x7fffe8001090 sd=27 pgs=216 cs=1 l=1).reader wants 240 from dispatch throttler 0/104857600
2012-06-21 16:25:18.826564 7ffff42f1700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6800/25236 pipe(0x7fffe8001090 sd=27 pgs=216 cs=1 l=1).aborted = 0
2012-06-21 16:25:18.826584 7ffff42f1700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6800/25236 pipe(0x7fffe8001090 sd=27 pgs=216 cs=1 l=1).reader got message 7 0x7fffd0003b80 mdsbeacon(4403/a up:boot seq 2243 v0) v2
2012-06-21 16:25:18.826618 7fffeeffd700 1 -- 127.0.0.1:6789/0 <== mds.? 127.0.0.1:6800/25236 7 ==== mdsbeacon(4403/a up:boot seq 2243 v0) v2 ==== 240+0+0 (1932240504 0 0) 0x7fffd0003b80 con 0x7fffe8002050
2012-06-21 16:25:18.826629 7fffedcf9700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6800/25236 pipe(0x7fffe8001090 sd=27 pgs=216 cs=1 l=1).writer: state = 2 policy.server=1
2012-06-21 16:25:18.826657 7fffedcf9700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6800/25236 pipe(0x7fffe8001090 sd=27 pgs=216 cs=1 l=1).write_ack 7
2012-06-21 16:25:18.826656 7fffeeffd700 10 mon.a@0(leader).paxosservice(mdsmap) dispatch mdsbeacon(4403/a up:boot seq 2243 v0) v2 from mds.? 127.0.0.1:6800/25236
2012-06-21 16:25:18.826683 7fffedcf9700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6800/25236 pipe(0x7fffe8001090 sd=27 pgs=216 cs=1 l=1).writer: state = 2 policy.server=1
2012-06-21 16:25:18.826754 7fffeeffd700 10 mon.a@0(leader).mds e1 preprocess_query mdsbeacon(4403/a up:boot seq 2243 v0) v2 from mds.? 127.0.0.1:6800/25236
2012-06-21 16:25:18.826776 7fffeeffd700 0 mon.a@0(leader).mds e1 preprocess_beason got MMDSBeacon from entity with insufficient privileges
2012-06-21 16:25:18.826785 7fffeeffd700 10 -- 127.0.0.1:6789/0 dispatch_throttle_release 240 to dispatch throttler 240/104857600
2012-06-21 16:25:19.184488 7fffee7fc700 7 mon.a@0(leader).paxos(paxos active c 1..51) extend_lease now+5 (2012-06-21 16:25:24.184486)
2012-06-21 16:25:19.184518 7fffee7fc700 1 -- 127.0.0.1:6789/0 --> mon.2 127.0.0.1:6791/0 -- paxos(lease lc 51 fc 1 pn 0 opn 0) v2 -- ?+0 0x7fffc0030110
2012-06-21 16:25:19.184637 7ffff44f3700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0x9347b0 sd=26 pgs=6 cs=1 l=0).writer: state = 2 policy.server=0
2012-06-21 16:25:19.184725 7ffff44f3700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0x9347b0 sd=26 pgs=6 cs=1 l=0).writer: state = 2 policy.server=0
2012-06-21 16:25:19.185186 7ffff41f0700 10 reader got ack seq 1622 >= 1622 on 0x7fffc0030110 paxos(lease lc 51 fc 1 pn 0 opn 0) v2
2012-06-21 16:25:19.185219 7ffff41f0700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0x9347b0 sd=26 pgs=6 cs=1 l=0).reader wants 80 from dispatch throttler 0/104857600
2012-06-21 16:25:19.185247 7ffff41f0700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0x9347b0 sd=26 pgs=6 cs=1 l=0).aborted = 0
2012-06-21 16:25:19.185264 7ffff41f0700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0x9347b0 sd=26 pgs=6 cs=1 l=0).reader got message 1589 0x7fffcc009610 paxos(lease_ack lc 51 fc 1 pn 0 opn 0) v2
2012-06-21 16:25:19.185294 7fffeeffd700 1 -- 127.0.0.1:6789/0 <== mon.2 127.0.0.1:6791/0 1589 ==== paxos(lease_ack lc 51 fc 1 pn 0 opn 0) v2 ==== 80+0+0 (1097150785 0 0) 0x7fffcc009610 con 0x934a20
2012-06-21 16:25:19.185318 7fffeeffd700 10 mon.a@0(leader).paxos(paxos active c 1..51) handle_lease_ack from mon.2 -- got everyone
2012-06-21 16:25:19.185303 7ffff44f3700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0x9347b0 sd=26 pgs=6 cs=1 l=0).writer: state = 2 policy.server=0
2012-06-21 16:25:19.185326 7ffff44f3700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0x9347b0 sd=26 pgs=6 cs=1 l=0).write_ack 1589
2012-06-21 16:25:19.185348 7ffff44f3700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0x9347b0 sd=26 pgs=6 cs=1 l=0).writer: state = 2 policy.server=0
2012-06-21 16:25:19.185409 7fffeeffd700 10 mon.a@0(leader).auth v15 update_from_paxos
2012-06-21 16:25:19.185440 7fffeeffd700 10 -- 127.0.0.1:6789/0 dispatch_throttle_release 80 to dispatch throttler 80/104857600
2012-06-21 16:25:20.291757 7fffedffb700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6801/25414 pipe(0x7fffe8001750 sd=29 pgs=209 cs=1 l=1).reader wants 240 from dispatch throttler 0/104857600
2012-06-21 16:25:20.291800 7fffedffb700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6801/25414 pipe(0x7fffe8001750 sd=29 pgs=209 cs=1 l=1).aborted = 0
2012-06-21 16:25:20.291825 7fffedffb700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6801/25414 pipe(0x7fffe8001750 sd=29 pgs=209 cs=1 l=1).reader got message 8 0x7fffdc001e80 mdsbeacon(4311/b up:boot seq 2243 v0) v2
2012-06-21 16:25:20.291857 7fffeeffd700 1 -- 127.0.0.1:6789/0 <== mds.? 127.0.0.1:6801/25414 8 ==== mdsbeacon(4311/b up:boot seq 2243 v0) v2 ==== 240+0+0 (3039885157 0 0) 0x7fffdc001e80 con 0x7fffe80019c0
2012-06-21 16:25:20.291882 7fffeeffd700 10 mon.a@0(leader).paxosservice(mdsmap) dispatch mdsbeacon(4311/b up:boot seq 2243 v0) v2 from mds.? 127.0.0.1:6801/25414
2012-06-21 16:25:20.291901 7fffedbf8700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6801/25414 pipe(0x7fffe8001750 sd=29 pgs=209 cs=1 l=1).writer: state = 2 policy.server=1
2012-06-21 16:25:20.291922 7fffedbf8700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6801/25414 pipe(0x7fffe8001750 sd=29 pgs=209 cs=1 l=1).write_ack 8
2012-06-21 16:25:20.291945 7fffedbf8700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6801/25414 pipe(0x7fffe8001750 sd=29 pgs=209 cs=1 l=1).writer: state = 2 policy.server=1
2012-06-21 16:25:20.291976 7fffeeffd700 10 mon.a@0(leader).mds e1 preprocess_query mdsbeacon(4311/b up:boot seq 2243 v0) v2 from mds.? 127.0.0.1:6801/25414
2012-06-21 16:25:20.292000 7fffeeffd700 0 mon.a@0(leader).mds e1 preprocess_beason got MMDSBeacon from entity with insufficient privileges
2012-06-21 16:25:20.292008 7fffeeffd700 10 -- 127.0.0.1:6789/0 dispatch_throttle_release 240 to dispatch throttler 240/104857600
2012-06-21 16:25:20.770733 7fffedefa700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6802/25594 pipe(0x7fffe8001b30 sd=28 pgs=201 cs=1 l=1).reader wants 240 from dispatch throttler 0/104857600
2012-06-21 16:25:20.770777 7fffedefa700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6802/25594 pipe(0x7fffe8001b30 sd=28 pgs=201 cs=1 l=1).aborted = 0
2012-06-21 16:25:20.770802 7fffedefa700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6802/25594 pipe(0x7fffe8001b30 sd=28 pgs=201 cs=1 l=1).reader got message 7 0x7fffc4005410 mdsbeacon(4409/c up:boot seq 2242 v0) v2
2012-06-21 16:25:20.770876 7ffff43f2700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6802/25594 pipe(0x7fffe8001b30 sd=28 pgs=201 cs=1 l=1).writer: state = 2 policy.server=1
2012-06-21 16:25:20.770914 7ffff43f2700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6802/25594 pipe(0x7fffe8001b30 sd=28 pgs=201 cs=1 l=1).write_ack 7
2012-06-21 16:25:20.770930 7fffeeffd700 1 -- 127.0.0.1:6789/0 <== mds.? 127.0.0.1:6802/25594 7 ==== mdsbeacon(4409/c up:boot seq 2242 v0) v2 ==== 240+0+0 (1591574214 0 0) 0x7fffc4005410 con 0x7fffe8001da0
2012-06-21 16:25:20.770946 7ffff43f2700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6802/25594 pipe(0x7fffe8001b30 sd=28 pgs=201 cs=1 l=1).writer: state = 2 policy.server=1
2012-06-21 16:25:20.770952 7fffeeffd700 10 mon.a@0(leader).paxosservice(mdsmap) dispatch mdsbeacon(4409/c up:boot seq 2242 v0) v2 from mds.? 127.0.0.1:6802/25594
2012-06-21 16:25:20.771021 7fffeeffd700 10 mon.a@0(leader).mds e1 preprocess_query mdsbeacon(4409/c up:boot seq 2242 v0) v2 from mds.? 127.0.0.1:6802/25594
2012-06-21 16:25:20.771038 7fffeeffd700 0 mon.a@0(leader).mds e1 preprocess_beason got MMDSBeacon from entity with insufficient privileges
2012-06-21 16:25:20.771044 7fffeeffd700 10 -- 127.0.0.1:6789/0 dispatch_throttle_release 240 to dispatch throttler 240/104857600
2012-06-21 16:25:22.184639 7fffee7fc700 7 mon.a@0(leader).paxos(paxos active c 1..51) extend_lease now+5 (2012-06-21 16:25:27.184638)
2012-06-21 16:25:22.184669 7fffee7fc700 1 -- 127.0.0.1:6789/0 --> mon.2 127.0.0.1:6791/0 -- paxos(lease lc 51 fc 1 pn 0 opn 0) v2 -- ?+0 0x7fffc0161460
2012-06-21 16:25:22.184787 7ffff44f3700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0x9347b0 sd=26 pgs=6 cs=1 l=0).writer: state = 2 policy.server=0
2012-06-21 16:25:22.184871 7ffff44f3700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0x9347b0 sd=26 pgs=6 cs=1 l=0).writer: state = 2 policy.server=0
2012-06-21 16:25:22.185208 7ffff41f0700 10 reader got ack seq 1623 >= 1623 on 0x7fffc0161460 paxos(lease lc 51 fc 1 pn 0 opn 0) v2
2012-06-21 16:25:22.185241 7ffff41f0700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0x9347b0 sd=26 pgs=6 cs=1 l=0).reader wants 80 from dispatch throttler 0/104857600
2012-06-21 16:25:22.185269 7ffff41f0700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0x9347b0 sd=26 pgs=6 cs=1 l=0).aborted = 0
2012-06-21 16:25:22.185286 7ffff41f0700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0x9347b0 sd=26 pgs=6 cs=1 l=0).reader got message 1590 0x7fffcc0533a0 paxos(lease_ack lc 51 fc 1 pn 0 opn 0) v2
2012-06-21 16:25:22.185378 7ffff44f3700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0x9347b0 sd=26 pgs=6 cs=1 l=0).writer: state = 2 policy.server=0
2012-06-21 16:25:22.185419 7ffff44f3700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0x9347b0 sd=26 pgs=6 cs=1 l=0).write_ack 1590
2012-06-21 16:25:22.185435 7fffeeffd700 1 -- 127.0.0.1:6789/0 <== mon.2 127.0.0.1:6791/0 1590 ==== paxos(lease_ack lc 51 fc 1 pn 0 opn 0) v2 ==== 80+0+0 (2824985556 0 0) 0x7fffcc0533a0 con 0x934a20
2012-06-21 16:25:22.185448 7ffff44f3700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6791/0 pipe(0x9347b0 sd=26 pgs=6 cs=1 l=0).writer: state = 2 policy.server=0
2012-06-21 16:25:22.185458 7fffeeffd700 10 mon.a@0(leader).paxos(paxos active c 1..51) handle_lease_ack from mon.2 -- got everyone
2012-06-21 16:25:22.185557 7fffeeffd700 10 mon.a@0(leader).auth v15 update_from_paxos
2012-06-21 16:25:22.185598 7fffeeffd700 10 -- 127.0.0.1:6789/0 dispatch_throttle_release 80 to dispatch throttler 80/104857600
2012-06-21 16:25:22.826816 7ffff42f1700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6800/25236 pipe(0x7fffe8001090 sd=27 pgs=216 cs=1 l=1).reader wants 240 from dispatch throttler 0/104857600
2012-06-21 16:25:22.826860 7ffff42f1700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6800/25236 pipe(0x7fffe8001090 sd=27 pgs=216 cs=1 l=1).aborted = 0
2012-06-21 16:25:22.826884 7ffff42f1700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6800/25236 pipe(0x7fffe8001090 sd=27 pgs=216 cs=1 l=1).reader got message 8 0x7fffd0004030 mdsbeacon(4403/a up:boot seq 2244 v0) v2
2012-06-21 16:25:22.826919 7fffedcf9700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6800/25236 pipe(0x7fffe8001090 sd=27 pgs=216 cs=1 l=1).writer: state = 2 policy.server=1
2012-06-21 16:25:22.826941 7fffedcf9700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6800/25236 pipe(0x7fffe8001090 sd=27 pgs=216 cs=1 l=1).write_ack 8
2012-06-21 16:25:22.826960 7fffedcf9700 10 -- 127.0.0.1:6789/0 >> 127.0.0.1:6800/25236 pipe(0x7fffe8001090 sd=27 pgs=216 cs=1 l=1).writer: state = 2 policy.server=1
This appears to be the same bug as #2620
- Status changed from New to Closed
Had to do with the AuthMonitor losing some infos when reading versions from the store.
This is fixed.
Also available in: Atom
PDF