You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@mesos.apache.org by "Vinod Kone (JIRA)" <ji...@apache.org> on 2014/06/24 23:52:24 UTC
[jira] [Commented] (MESOS-1514)
AllocatorZooKeeperTest/0.FrameworkReregistersFirst is flaky
[ https://issues.apache.org/jira/browse/MESOS-1514?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14042747#comment-14042747 ]
Vinod Kone commented on MESOS-1514:
-----------------------------------
https://reviews.apache.org/r/22945/
> AllocatorZooKeeperTest/0.FrameworkReregistersFirst is flaky
> -----------------------------------------------------------
>
> Key: MESOS-1514
> URL: https://issues.apache.org/jira/browse/MESOS-1514
> Project: Mesos
> Issue Type: Bug
> Components: test
> Affects Versions: 0.19.0
> Reporter: Dominic Hamon
> Assignee: Vinod Kone
>
> {{noformat}}
> [ RUN ] AllocatorZooKeeperTest/0.FrameworkReregistersFirst
> Using temporary directory '/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_iCI9kS'
> I0618 18:36:00.964223 20920 leveldb.cpp:176] Opened db in 36.617742ms
> I0618 18:36:00.974045 20920 leveldb.cpp:183] Compacted db in 9.529108ms
> I0618 18:36:00.974359 20920 leveldb.cpp:198] Created db iterator in 7243ns
> I0618 18:36:00.974510 20920 leveldb.cpp:204] Seeked to beginning of db in 1949ns
> I0618 18:36:00.974699 20920 leveldb.cpp:273] Iterated through 0 keys in the db in 1680ns
> I0618 18:36:00.974900 20920 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
> 2014-06-18 18:36:00,975:20920(0x2b89c93f8700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
> 2014-06-18 18:36:00,975:20920(0x2b89c93f8700):ZOO_INFO@log_env@716: Client environment:host.name=lucid
> 2014-06-18 18:36:00,975:20920(0x2b89c93f8700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
> 2014-06-18 18:36:00,975:20920(0x2b89c93f8700):ZOO_INFO@log_env@724: Client environment:os.arch=2.6.32-61-generic
> 2014-06-18 18:36:00,975:20920(0x2b89c93f8700):ZOO_INFO@log_env@725: Client environment:os.version=#124-Ubuntu SMP Wed Jun 4 23:03:27 UTC 2014
> 2014-06-18 18:36:00,975:20920(0x2b89c93f8700):ZOO_INFO@log_env@733: Client environment:user.name=(null)
> 2014-06-18 18:36:00,975:20920(0x2b89c93f8700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
> 2014-06-18 18:36:00,975:20920(0x2b89c93f8700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_iCI9kS
> 2014-06-18 18:36:00,975:20920(0x2b89c93f8700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:57094 sessionTimeout=10000 watcher=0x2b89c40f5110 sessionId=0 sessionPasswd=<null> context=0x1929df0 flags=0
> 2014-06-18 18:36:00,975:20920(0x2b89c9bfc700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
> 2014-06-18 18:36:00,975:20920(0x2b89c9bfc700):ZOO_INFO@log_env@716: Client environment:host.name=lucid
> 2014-06-18 18:36:00,976:20920(0x2b89c9bfc700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
> 2014-06-18 18:36:00,976:20920(0x2b89c9bfc700):ZOO_INFO@log_env@724: Client environment:os.arch=2.6.32-61-generic
> 2014-06-18 18:36:00,976:20920(0x2b89c9bfc700):ZOO_INFO@log_env@725: Client environment:os.version=#124-Ubuntu SMP Wed Jun 4 23:03:27 UTC 2014
> 2014-06-18 18:36:00,976:20920(0x2b89c9bfc700):ZOO_INFO@log_env@733: Client environment:user.name=(null)
> 2014-06-18 18:36:00,976:20920(0x2b89c9bfc700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
> 2014-06-18 18:36:00,976:20920(0x2b89c9bfc700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_iCI9kS
> 2014-06-18 18:36:00,976:20920(0x2b89c9bfc700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:57094 sessionTimeout=10000 watcher=0x2b89c40f5110 sessionId=0 sessionPasswd=<null> context=0x2b89cc28c4e0 flags=0
> I0618 18:36:00.976397 20944 log.cpp:238] Attempting to join replica to ZooKeeper group
> I0618 18:36:00.976559 20944 recover.cpp:425] Starting replica recovery
> I0618 18:36:00.976629 20944 recover.cpp:451] Replica is in EMPTY status
> I0618 18:36:00.977013 20944 replica.cpp:638] Replica in EMPTY status received a broadcasted recover request
> I0618 18:36:00.977077 20944 recover.cpp:188] Received a recover response from a replica in EMPTY status
> I0618 18:36:00.977195 20944 recover.cpp:542] Updating replica status to STARTING
> 2014-06-18 18:36:00,978:20920(0x2b89c97fa700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
> 2014-06-18 18:36:00,978:20920(0x2b89c97fa700):ZOO_INFO@log_env@716: Client environment:host.name=lucid
> 2014-06-18 18:36:00,978:20920(0x2b89c97fa700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
> 2014-06-18 18:36:00,978:20920(0x2b89c97fa700):ZOO_INFO@log_env@724: Client environment:os.arch=2.6.32-61-generic
> 2014-06-18 18:36:00,978:20920(0x2b89c97fa700):ZOO_INFO@log_env@725: Client environment:os.version=#124-Ubuntu SMP Wed Jun 4 23:03:27 UTC 2014
> 2014-06-18 18:36:00,978:20920(0x2b89c97fa700):ZOO_INFO@log_env@733: Client environment:user.name=(null)
> 2014-06-18 18:36:00,978:20920(0x2b89c97fa700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
> 2014-06-18 18:36:00,978:20920(0x2b89c97fa700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_iCI9kS
> 2014-06-18 18:36:00,978:20920(0x2b89c97fa700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:57094 sessionTimeout=10000 watcher=0x2b89c40f5110 sessionId=0 sessionPasswd=<null> context=0x2b89cc2a45f0 flags=0
> 2014-06-18 18:36:00,978:20920(0x2b89c91f7700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
> 2014-06-18 18:36:00,978:20920(0x2b89c91f7700):ZOO_INFO@log_env@716: Client environment:host.name=lucid
> 2014-06-18 18:36:00,978:20920(0x2b89c91f7700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
> 2014-06-18 18:36:00,978:20920(0x2b89c91f7700):ZOO_INFO@log_env@724: Client environment:os.arch=2.6.32-61-generic
> 2014-06-18 18:36:00,978:20920(0x2b89c91f7700):ZOO_INFO@log_env@725: Client environment:os.version=#124-Ubuntu SMP Wed Jun 4 23:03:27 UTC 2014
> 2014-06-18 18:36:00,978:20920(0x2b89c91f7700):ZOO_INFO@log_env@733: Client environment:user.name=(null)
> 2014-06-18 18:36:00,978:20920(0x2b89c91f7700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
> 2014-06-18 18:36:00,978:20920(0x2b89c91f7700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_iCI9kS
> 2014-06-18 18:36:00,978:20920(0x2b89c91f7700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:57094 sessionTimeout=10000 watcher=0x2b89c40f5110 sessionId=0 sessionPasswd=<null> context=0x19b2f10 flags=0
> I0618 18:36:00.981142 20942 master.cpp:286] Master 20140618-183600-16842879-58874-20920 (lucid) started on 127.0.1.1:58874
> I0618 18:36:00.981168 20942 master.cpp:323] Master only allowing authenticated frameworks to register
> I0618 18:36:00.981173 20942 master.cpp:328] Master only allowing authenticated slaves to register
> I0618 18:36:00.981180 20942 credentials.hpp:35] Loading credentials for authentication from '/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_iCI9kS/credentials'
> I0618 18:36:00.981252 20942 master.cpp:354] Authorization enabled
> I0618 18:36:00.981689 20942 hierarchical_allocator_process.hpp:301] Initializing hierarchical allocator process with master : master@127.0.1.1:58874
> I0618 18:36:00.981734 20942 master.cpp:120] No whitelist given. Advertising offers for all slaves
> I0618 18:36:00.981992 20942 contender.cpp:131] Joining the ZK group
> 2014-06-18 18:36:00,985:20920(0x2b89d4c47700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:57094]
> 2014-06-18 18:36:00,986:20920(0x2b89d5049700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:57094]
> I0618 18:36:00.987141 20944 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 9.850398ms
> I0618 18:36:00.987725 20944 replica.cpp:320] Persisted replica status to STARTING
> I0618 18:36:00.987854 20944 recover.cpp:451] Replica is in STARTING status
> I0618 18:36:00.988219 20944 replica.cpp:638] Replica in STARTING status received a broadcasted recover request
> I0618 18:36:00.988286 20944 recover.cpp:188] Received a recover response from a replica in STARTING status
> I0618 18:36:00.988389 20944 recover.cpp:542] Updating replica status to VOTING
> 2014-06-18 18:36:00,989:20920(0x2b89d545f700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:57094]
> 2014-06-18 18:36:00,989:20920(0x2b89d4e48700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:57094]
> 2014-06-18 18:36:00,999:20920(0x2b89d4c47700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:57094], sessionId=0x146b1c427990000, negotiated timeout=10000
> I0618 18:36:01.000825 20946 group.cpp:313] Group process (group(10)@127.0.1.1:58874) connected to ZooKeeper
> I0618 18:36:01.000860 20946 group.cpp:787] Syncing group operations: queue size (joins, cancels, datas) = (0, 0, 0)
> I0618 18:36:01.000871 20946 group.cpp:385] Trying to create path '/znode/log_replicas' in ZooKeeper
> I0618 18:36:01.007729 20944 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 19.269579ms
> I0618 18:36:01.007776 20944 replica.cpp:320] Persisted replica status to VOTING
> I0618 18:36:01.007877 20944 recover.cpp:556] Successfully joined the Paxos group
> I0618 18:36:01.007952 20944 recover.cpp:440] Recover process terminated
> 2014-06-18 18:36:01,013:20920(0x2b89d5049700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:57094], sessionId=0x146b1c427990001, negotiated timeout=10000
> I0618 18:36:01.013653 20944 group.cpp:313] Group process (group(11)@127.0.1.1:58874) connected to ZooKeeper
> I0618 18:36:01.013689 20944 group.cpp:787] Syncing group operations: queue size (joins, cancels, datas) = (1, 0, 0)
> I0618 18:36:01.013705 20944 group.cpp:385] Trying to create path '/znode/log_replicas' in ZooKeeper
> 2014-06-18 18:36:01,015:20920(0x2b89d545f700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:57094], sessionId=0x146b1c427990002, negotiated timeout=10000
> I0618 18:36:01.015651 20941 group.cpp:313] Group process (group(13)@127.0.1.1:58874) connected to ZooKeeper
> I0618 18:36:01.015681 20941 group.cpp:787] Syncing group operations: queue size (joins, cancels, datas) = (0, 0, 0)
> I0618 18:36:01.015696 20941 group.cpp:385] Trying to create path '/znode' in ZooKeeper
> 2014-06-18 18:36:01,017:20920(0x2b89d4e48700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:57094], sessionId=0x146b1c427990003, negotiated timeout=10000
> I0618 18:36:01.017316 20943 group.cpp:313] Group process (group(12)@127.0.1.1:58874) connected to ZooKeeper
> I0618 18:36:01.017333 20943 group.cpp:787] Syncing group operations: queue size (joins, cancels, datas) = (1, 0, 0)
> I0618 18:36:01.017341 20943 group.cpp:385] Trying to create path '/znode' in ZooKeeper
> I0618 18:36:01.048796 20947 contender.cpp:247] New candidate (id='0') has entered the contest for leadership
> I0618 18:36:01.051983 20942 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
> I0618 18:36:01.052057 20942 detector.cpp:138] Detected a new leader: (id='0')
> I0618 18:36:01.052237 20942 group.cpp:658] Trying to get '/znode/info_0000000000' in ZooKeeper
> I0618 18:36:01.053251 20943 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
> I0618 18:36:01.066527 20942 detector.cpp:382] A new leading master (UPID=master@127.0.1.1:58874) is detected
> I0618 18:36:01.066608 20942 master.cpp:1077] The newly elected leader is master@127.0.1.1:58874 with id 20140618-183600-16842879-58874-20920
> I0618 18:36:01.066623 20942 master.cpp:1090] Elected as the leading master!
> I0618 18:36:01.066629 20942 master.cpp:908] Recovering from registrar
> I0618 18:36:01.066725 20942 registrar.cpp:313] Recovering registrar
> I0618 18:36:01.066973 20942 log.cpp:656] Attempting to start the writer
> I0618 18:36:01.067306 20942 replica.cpp:474] Replica received implicit promise request with proposal 1
> I0618 18:36:01.077672 20940 network.hpp:423] ZooKeeper group memberships changed
> I0618 18:36:01.077810 20940 group.cpp:658] Trying to get '/znode/log_replicas/0000000000' in ZooKeeper
> I0618 18:36:01.078409 20942 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 11.081579ms
> I0618 18:36:01.078593 20942 replica.cpp:342] Persisted promised to 1
> I0618 18:36:01.078833 20942 coordinator.cpp:230] Coordinator attemping to fill missing position
> I0618 18:36:01.079159 20942 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2
> I0618 18:36:01.081147 20940 network.hpp:461] ZooKeeper group PIDs: { log-replica(91)@127.0.1.1:58874 }
> I0618 18:36:01.088752 20942 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 9.563553ms
> I0618 18:36:01.088803 20942 replica.cpp:676] Persisted action at 0
> I0618 18:36:01.089141 20942 replica.cpp:508] Replica received write request for position 0
> I0618 18:36:01.089174 20942 leveldb.cpp:438] Reading position from leveldb took 18873ns
> I0618 18:36:01.101352 20942 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 12.142775ms
> I0618 18:36:01.101652 20942 replica.cpp:676] Persisted action at 0
> I0618 18:36:01.102083 20942 replica.cpp:655] Replica received learned notice for position 0
> I0618 18:36:01.111604 20942 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 9.229356ms
> I0618 18:36:01.111886 20942 replica.cpp:676] Persisted action at 0
> I0618 18:36:01.112315 20942 replica.cpp:661] Replica learned NOP action at position 0
> I0618 18:36:01.116452 20947 log.cpp:672] Writer started with ending position 0
> I0618 18:36:01.116791 20947 leveldb.cpp:438] Reading position from leveldb took 95675ns
> I0618 18:36:01.118211 20947 registrar.cpp:346] Successfully fetched the registry (0B)
> I0618 18:36:01.118233 20947 registrar.cpp:422] Attempting to update the 'registry'
> I0618 18:36:01.119446 20947 log.cpp:680] Attempting to append 118 bytes to the log
> I0618 18:36:01.119493 20947 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1
> I0618 18:36:01.119699 20947 replica.cpp:508] Replica received write request for position 1
> I0618 18:36:01.130266 20947 leveldb.cpp:343] Persisting action (135 bytes) to leveldb took 10.535898ms
> I0618 18:36:01.130524 20947 replica.cpp:676] Persisted action at 1
> I0618 18:36:01.137030 20946 replica.cpp:655] Replica received learned notice for position 1
> I0618 18:36:01.148303 20946 leveldb.cpp:343] Persisting action (137 bytes) to leveldb took 11.222229ms
> I0618 18:36:01.148530 20946 replica.cpp:676] Persisted action at 1
> I0618 18:36:01.148545 20946 replica.cpp:661] Replica learned APPEND action at position 1
> I0618 18:36:01.149046 20946 registrar.cpp:479] Successfully updated 'registry'
> I0618 18:36:01.149101 20946 registrar.cpp:372] Successfully recovered registrar
> I0618 18:36:01.149147 20946 log.cpp:699] Attempting to truncate the log to 1
> I0618 18:36:01.149250 20946 master.cpp:935] Recovered 0 slaves from the Registry (82B) ; allowing 10mins for slaves to re-register
> I0618 18:36:01.149293 20946 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2
> I0618 18:36:01.149749 20943 replica.cpp:508] Replica received write request for position 2
> I0618 18:36:01.152480 20920 sched.cpp:139] Version: 0.20.0
> I0618 18:36:01.152762 20944 slave.cpp:143] Slave started on 8)@127.0.1.1:58874
> I0618 18:36:01.152777 20944 credentials.hpp:35] Loading credentials for authentication from '/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_IGQDEk/credential'
> I0618 18:36:01.152828 20944 slave.cpp:243] Slave using credential for: test-principal
> I0618 18:36:01.153127 20944 slave.cpp:256] Slave resources: cpus(*):2; mem(*):1024; disk(*):25759; ports(*):[31000-32000]
> I0618 18:36:01.153189 20944 slave.cpp:284] Slave hostname: lucid
> I0618 18:36:01.153199 20944 slave.cpp:285] Slave checkpoint: false
> 2014-06-18 18:36:01,153:20920(0x2b89c99fb700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
> 2014-06-18 18:36:01,153:20920(0x2b89c99fb700):ZOO_INFO@log_env@716: Client environment:host.name=lucid
> 2014-06-18 18:36:01,153:20920(0x2b89c99fb700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
> 2014-06-18 18:36:01,153:20920(0x2b89c99fb700):ZOO_INFO@log_env@724: Client environment:os.arch=2.6.32-61-generic
> 2014-06-18 18:36:01,153:20920(0x2b89c99fb700):ZOO_INFO@log_env@725: Client environment:os.version=#124-Ubuntu SMP Wed Jun 4 23:03:27 UTC 2014
> 2014-06-18 18:36:01,153:20920(0x2b89c99fb700):ZOO_INFO@log_env@733: Client environment:user.name=(null)
> 2014-06-18 18:36:01,153:20920(0x2b89c99fb700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
> 2014-06-18 18:36:01,153:20920(0x2b89c99fb700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_iCI9kS
> 2014-06-18 18:36:01,153:20920(0x2b89c99fb700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:57094 sessionTimeout=10000 watcher=0x2b89c40f5110 sessionId=0 sessionPasswd=<null> context=0x2b89cc33c800 flags=0
> I0618 18:36:01.153949 20945 state.cpp:33] Recovering state from '/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_IGQDEk/meta'
> 2014-06-18 18:36:01,154:20920(0x2b89c9bfc700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
> 2014-06-18 18:36:01,154:20920(0x2b89c9bfc700):ZOO_INFO@log_env@716: Client environment:host.name=lucid
> 2014-06-18 18:36:01,154:20920(0x2b89c9bfc700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
> 2014-06-18 18:36:01,154:20920(0x2b89c9bfc700):ZOO_INFO@log_env@724: Client environment:os.arch=2.6.32-61-generic
> 2014-06-18 18:36:01,154:20920(0x2b89c9bfc700):ZOO_INFO@log_env@725: Client environment:os.version=#124-Ubuntu SMP Wed Jun 4 23:03:27 UTC 2014
> 2014-06-18 18:36:01,154:20920(0x2b89c9bfc700):ZOO_INFO@log_env@733: Client environment:user.name=(null)
> 2014-06-18 18:36:01,154:20920(0x2b89c9bfc700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
> 2014-06-18 18:36:01,154:20920(0x2b89c9bfc700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_iCI9kS
> 2014-06-18 18:36:01,154:20920(0x2b89c9bfc700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:57094 sessionTimeout=10000 watcher=0x2b89c40f5110 sessionId=0 sessionPasswd=<null> context=0x2b89cc029530 flags=0
> I0618 18:36:01.154368 20947 status_update_manager.cpp:193] Recovering status update manager
> I0618 18:36:01.154450 20947 slave.cpp:3068] Finished recovery
> 2014-06-18 18:36:01,156:20920(0x2b89d7058700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:57094]
> 2014-06-18 18:36:01,159:20920(0x2b89d745a700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:57094]
> I0618 18:36:01.166663 20943 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 16.860034ms
> I0618 18:36:01.166765 20943 replica.cpp:676] Persisted action at 2
> I0618 18:36:01.167064 20943 replica.cpp:655] Replica received learned notice for position 2
> 2014-06-18 18:36:01,173:20920(0x2b89d7058700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:57094], sessionId=0x146b1c427990004, negotiated timeout=10000
> I0618 18:36:01.174965 20941 group.cpp:313] Group process (group(14)@127.0.1.1:58874) connected to ZooKeeper
> I0618 18:36:01.174990 20941 group.cpp:787] Syncing group operations: queue size (joins, cancels, datas) = (0, 0, 0)
> I0618 18:36:01.175000 20941 group.cpp:385] Trying to create path '/znode' in ZooKeeper
> 2014-06-18 18:36:01,179:20920(0x2b89d745a700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:57094], sessionId=0x146b1c427990005, negotiated timeout=10000
> I0618 18:36:01.183410 20943 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 16.317381ms
> I0618 18:36:01.184677 20943 leveldb.cpp:401] Deleting ~1 keys from leveldb took 51759ns
> I0618 18:36:01.184696 20943 replica.cpp:676] Persisted action at 2
> I0618 18:36:01.184705 20943 replica.cpp:661] Replica learned TRUNCATE action at position 2
> I0618 18:36:01.185336 20943 group.cpp:313] Group process (group(15)@127.0.1.1:58874) connected to ZooKeeper
> I0618 18:36:01.185356 20943 group.cpp:787] Syncing group operations: queue size (joins, cancels, datas) = (0, 0, 0)
> I0618 18:36:01.185365 20943 group.cpp:385] Trying to create path '/znode' in ZooKeeper
> I0618 18:36:01.190943 20941 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
> I0618 18:36:01.191020 20941 detector.cpp:138] Detected a new leader: (id='0')
> I0618 18:36:01.191124 20941 group.cpp:658] Trying to get '/znode/info_0000000000' in ZooKeeper
> I0618 18:36:01.192544 20941 detector.cpp:382] A new leading master (UPID=master@127.0.1.1:58874) is detected
> I0618 18:36:01.192606 20941 slave.cpp:537] New master detected at master@127.0.1.1:58874
> I0618 18:36:01.192628 20941 slave.cpp:613] Authenticating with master master@127.0.1.1:58874
> I0618 18:36:01.192672 20941 slave.cpp:586] Detecting new master
> I0618 18:36:01.192711 20941 status_update_manager.cpp:167] New master detected at master@127.0.1.1:58874
> I0618 18:36:01.192749 20941 authenticatee.hpp:128] Creating new client SASL connection
> I0618 18:36:01.192847 20941 master.cpp:3457] Authenticating slave(8)@127.0.1.1:58874
> I0618 18:36:01.192939 20941 authenticator.hpp:156] Creating new server SASL connection
> I0618 18:36:01.192998 20941 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
> I0618 18:36:01.193011 20941 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0618 18:36:01.193032 20941 authenticator.hpp:262] Received SASL authentication start
> I0618 18:36:01.193081 20941 authenticator.hpp:384] Authentication requires more steps
> I0618 18:36:01.193106 20941 authenticatee.hpp:265] Received SASL authentication step
> I0618 18:36:01.193150 20941 authenticator.hpp:290] Received SASL authentication step
> I0618 18:36:01.193171 20941 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'lucid' server FQDN: 'lucid' SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0618 18:36:01.193177 20941 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
> I0618 18:36:01.193186 20941 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0618 18:36:01.193194 20941 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'lucid' server FQDN: 'lucid' SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0618 18:36:01.193199 20941 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0618 18:36:01.193204 20941 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0618 18:36:01.193215 20941 authenticator.hpp:376] Authentication success
> I0618 18:36:01.193241 20941 authenticatee.hpp:305] Authentication success
> I0618 18:36:01.193263 20941 master.cpp:3497] Successfully authenticated principal 'test-principal' at slave(8)@127.0.1.1:58874
> I0618 18:36:01.193326 20941 slave.cpp:670] Successfully authenticated with master master@127.0.1.1:58874
> I0618 18:36:01.193373 20941 slave.cpp:908] Will retry registration in 18.944771ms if necessary
> I0618 18:36:01.193462 20940 master.cpp:2736] Registering slave at slave(8)@127.0.1.1:58874 (lucid) with id 20140618-183600-16842879-58874-20920-0
> I0618 18:36:01.193562 20940 registrar.cpp:422] Attempting to update the 'registry'
> I0618 18:36:01.194854 20942 log.cpp:680] Attempting to append 289 bytes to the log
> I0618 18:36:01.194906 20942 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3
> I0618 18:36:01.195130 20942 replica.cpp:508] Replica received write request for position 3
> I0618 18:36:01.195433 20943 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
> I0618 18:36:01.195519 20943 detector.cpp:138] Detected a new leader: (id='0')
> I0618 18:36:01.195611 20943 group.cpp:658] Trying to get '/znode/info_0000000000' in ZooKeeper
> I0618 18:36:01.196873 20943 detector.cpp:382] A new leading master (UPID=master@127.0.1.1:58874) is detected
> I0618 18:36:01.196935 20943 sched.cpp:235] New master detected at master@127.0.1.1:58874
> I0618 18:36:01.196949 20943 sched.cpp:285] Authenticating with master master@127.0.1.1:58874
> I0618 18:36:01.197028 20943 authenticatee.hpp:128] Creating new client SASL connection
> I0618 18:36:01.197103 20943 master.cpp:3457] Authenticating scheduler-1dd718fb-d1c6-459b-8ecd-b4a1974ea7f9@127.0.1.1:58874
> I0618 18:36:01.197195 20943 authenticator.hpp:156] Creating new server SASL connection
> I0618 18:36:01.197249 20943 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
> I0618 18:36:01.197262 20943 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0618 18:36:01.197281 20943 authenticator.hpp:262] Received SASL authentication start
> I0618 18:36:01.197317 20943 authenticator.hpp:384] Authentication requires more steps
> I0618 18:36:01.197341 20943 authenticatee.hpp:265] Received SASL authentication step
> I0618 18:36:01.197371 20943 authenticator.hpp:290] Received SASL authentication step
> I0618 18:36:01.197382 20943 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'lucid' server FQDN: 'lucid' SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0618 18:36:01.197389 20943 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
> I0618 18:36:01.197397 20943 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0618 18:36:01.197404 20943 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'lucid' server FQDN: 'lucid' SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0618 18:36:01.197409 20943 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0618 18:36:01.197414 20943 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0618 18:36:01.197424 20943 authenticator.hpp:376] Authentication success
> I0618 18:36:01.197448 20943 authenticatee.hpp:305] Authentication success
> I0618 18:36:01.197466 20943 master.cpp:3497] Successfully authenticated principal 'test-principal' at scheduler-1dd718fb-d1c6-459b-8ecd-b4a1974ea7f9@127.0.1.1:58874
> I0618 18:36:01.197525 20943 sched.cpp:359] Successfully authenticated with master master@127.0.1.1:58874
> I0618 18:36:01.197537 20943 sched.cpp:478] Sending registration request to master@127.0.1.1:58874
> I0618 18:36:01.197581 20943 master.cpp:1196] Received registration request from scheduler-1dd718fb-d1c6-459b-8ecd-b4a1974ea7f9@127.0.1.1:58874
> I0618 18:36:01.197598 20943 master.cpp:1156] Authorizing framework principal 'test-principal' to receive offers for role '*'
> I0618 18:36:01.197711 20943 master.cpp:1255] Registering framework 20140618-183600-16842879-58874-20920-0000 at scheduler-1dd718fb-d1c6-459b-8ecd-b4a1974ea7f9@127.0.1.1:58874
> I0618 18:36:01.197814 20943 sched.cpp:409] Framework registered with 20140618-183600-16842879-58874-20920-0000
> I0618 18:36:01.197846 20943 sched.cpp:423] Scheduler::registered took 12921ns
> I0618 18:36:01.197885 20943 hierarchical_allocator_process.hpp:331] Added framework 20140618-183600-16842879-58874-20920-0000
> I0618 18:36:01.197892 20943 hierarchical_allocator_process.hpp:724] No resources available to allocate!
> I0618 18:36:01.197897 20943 hierarchical_allocator_process.hpp:686] Performed allocation for 0 slaves in 5584ns
> I0618 18:36:01.216913 20946 slave.cpp:908] Will retry registration in 20.484054ms if necessary
> I0618 18:36:01.217005 20946 master.cpp:2724] Ignoring register slave message from slave(8)@127.0.1.1:58874 (lucid) as admission is already in progress
> I0618 18:36:01.247066 20946 slave.cpp:908] Will retry registration in 50.388056ms if necessary
> I0618 18:36:01.247161 20946 master.cpp:2724] Ignoring register slave message from slave(8)@127.0.1.1:58874 (lucid) as admission is already in progress
> I0618 18:36:01.306948 20946 slave.cpp:908] Will retry registration in 130.230271ms if necessary
> I0618 18:36:01.307051 20946 master.cpp:2724] Ignoring register slave message from slave(8)@127.0.1.1:58874 (lucid) as admission is already in progress
> I0618 18:36:01.446940 20946 slave.cpp:908] Will retry registration in 138.765169ms if necessary
> I0618 18:36:01.447062 20946 master.cpp:2724] Ignoring register slave message from slave(8)@127.0.1.1:58874 (lucid) as admission is already in progress
> I0618 18:36:01.542963 20942 leveldb.cpp:343] Persisting action (308 bytes) to leveldb took 347.786977ms
> I0618 18:36:01.543016 20942 replica.cpp:676] Persisted action at 3
> I0618 18:36:01.543288 20942 replica.cpp:655] Replica received learned notice for position 3
> I0618 18:36:01.563463 20942 leveldb.cpp:343] Persisting action (310 bytes) to leveldb took 20.139769ms
> I0618 18:36:01.563518 20942 replica.cpp:676] Persisted action at 3
> I0618 18:36:01.563526 20942 replica.cpp:661] Replica learned APPEND action at position 3
> I0618 18:36:01.563928 20942 registrar.cpp:479] Successfully updated 'registry'
> I0618 18:36:01.564012 20942 log.cpp:699] Attempting to truncate the log to 3
> I0618 18:36:01.564070 20942 master.cpp:2776] Registered slave 20140618-183600-16842879-58874-20920-0 at slave(8)@127.0.1.1:58874 (lucid)
> I0618 18:36:01.564086 20942 master.cpp:3923] Adding slave 20140618-183600-16842879-58874-20920-0 at slave(8)@127.0.1.1:58874 (lucid) with cpus(*):2; mem(*):1024; disk(*):25759; ports(*):[31000-32000]
> I0618 18:36:01.564200 20942 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4
> I0618 18:36:01.564275 20942 slave.cpp:704] Registered with master master@127.0.1.1:58874; given slave ID 20140618-183600-16842879-58874-20920-0
> I0618 18:36:01.564339 20942 hierarchical_allocator_process.hpp:444] Added slave 20140618-183600-16842879-58874-20920-0 (lucid) with cpus(*):2; mem(*):1024; disk(*):25759; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):25759; ports(*):[31000-32000] available)
> I0618 18:36:01.564393 20942 hierarchical_allocator_process.hpp:750] Offering cpus(*):2; mem(*):1024; disk(*):25759; ports(*):[31000-32000] on slave 20140618-183600-16842879-58874-20920-0 to framework 20140618-183600-16842879-58874-20920-0000
> I0618 18:36:01.564476 20942 hierarchical_allocator_process.hpp:706] Performed allocation for slave 20140618-183600-16842879-58874-20920-0 in 107379ns
> I0618 18:36:01.564568 20942 master.hpp:785] Adding offer 20140618-183600-16842879-58874-20920-0 with resources cpus(*):2; mem(*):1024; disk(*):25759; ports(*):[31000-32000] on slave 20140618-183600-16842879-58874-20920-0 (lucid)
> I0618 18:36:01.564610 20942 master.cpp:3404] Sending 1 offers to framework 20140618-183600-16842879-58874-20920-0000
> I0618 18:36:01.564885 20942 sched.cpp:546] Scheduler::resourceOffers took 145554ns
> I0618 18:36:01.565054 20942 master.hpp:795] Removing offer 20140618-183600-16842879-58874-20920-0 with resources cpus(*):2; mem(*):1024; disk(*):25759; ports(*):[31000-32000] on slave 20140618-183600-16842879-58874-20920-0 (lucid)
> I0618 18:36:01.565101 20942 master.cpp:2080] Processing reply for offers: [ 20140618-183600-16842879-58874-20920-0 ] on slave 20140618-183600-16842879-58874-20920-0 at slave(8)@127.0.1.1:58874 (lucid) for framework 20140618-183600-16842879-58874-20920-0000
> I0618 18:36:01.565124 20942 master.cpp:2166] Authorizing framework principal 'test-principal' to launch task 0 as user 'jenkins'
> I0618 18:36:01.565438 20942 master.hpp:757] Adding task 0 with resources cpus(*):1; mem(*):500 on slave 20140618-183600-16842879-58874-20920-0 (lucid)
> I0618 18:36:01.565462 20942 master.cpp:2232] Launching task 0 of framework 20140618-183600-16842879-58874-20920-0000 with resources cpus(*):1; mem(*):500 on slave 20140618-183600-16842879-58874-20920-0 at slave(8)@127.0.1.1:58874 (lucid)
> I0618 18:36:01.565578 20942 replica.cpp:508] Replica received write request for position 4
> I0618 18:36:01.565723 20946 slave.cpp:939] Got assigned task 0 for framework 20140618-183600-16842879-58874-20920-0000
> I0618 18:36:01.565913 20946 slave.cpp:1049] Launching task 0 for framework 20140618-183600-16842879-58874-20920-0000
> I0618 18:36:01.567560 20941 hierarchical_allocator_process.hpp:546] Framework 20140618-183600-16842879-58874-20920-0000 left cpus(*):1; mem(*):524; disk(*):25759; ports(*):[31000-32000] unused on slave 20140618-183600-16842879-58874-20920-0
> I0618 18:36:01.567634 20941 hierarchical_allocator_process.hpp:588] Framework 20140618-183600-16842879-58874-20920-0000 filtered slave 20140618-183600-16842879-58874-20920-0 for 5secs
> I0618 18:36:01.568872 20946 exec.cpp:131] Version: 0.20.0
> I0618 18:36:01.569183 20943 exec.cpp:181] Executor started at: executor(2)@127.0.1.1:58874 with pid 20920
> I0618 18:36:01.569425 20946 slave.cpp:1159] Queuing task '0' for executor default of framework '20140618-183600-16842879-58874-20920-0000
> I0618 18:36:01.569633 20946 slave.cpp:498] Successfully attached file '/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_IGQDEk/slaves/20140618-183600-16842879-58874-20920-0/frameworks/20140618-183600-16842879-58874-20920-0000/executors/default/runs/7e7364b7-0e92-41f5-a1d8-3d1c0357a4c7'
> I0618 18:36:01.569823 20946 slave.cpp:1670] Got registration for executor 'default' of framework 20140618-183600-16842879-58874-20920-0000
> I0618 18:36:01.570102 20940 exec.cpp:205] Executor registered on slave 20140618-183600-16842879-58874-20920-0
> I0618 18:36:01.571108 20940 exec.cpp:217] Executor::registered took 14153ns
> I0618 18:36:01.571229 20946 slave.cpp:1789] Flushing queued task 0 for executor 'default' of framework 20140618-183600-16842879-58874-20920-0000
> I0618 18:36:01.571475 20944 exec.cpp:292] Executor asked to run task '0'
> I0618 18:36:01.571511 20944 exec.cpp:301] Executor::launchTask took 20286ns
> I0618 18:36:01.572502 20944 exec.cpp:524] Executor sending status update TASK_RUNNING (UUID: 9fbf7005-8849-4f61-9f9b-e973d730097a) for task 0 of framework 20140618-183600-16842879-58874-20920-0000
> I0618 18:36:01.572659 20946 slave.cpp:2405] Monitoring executor 'default' of framework '20140618-183600-16842879-58874-20920-0000' in container '7e7364b7-0e92-41f5-a1d8-3d1c0357a4c7'
> I0618 18:36:01.572962 20946 slave.cpp:2024] Handling status update TASK_RUNNING (UUID: 9fbf7005-8849-4f61-9f9b-e973d730097a) for task 0 of framework 20140618-183600-16842879-58874-20920-0000 from executor(2)@127.0.1.1:58874
> I0618 18:36:01.573190 20940 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: 9fbf7005-8849-4f61-9f9b-e973d730097a) for task 0 of framework 20140618-183600-16842879-58874-20920-0000
> I0618 18:36:01.573348 20940 status_update_manager.cpp:499] Creating StatusUpdate stream for task 0 of framework 20140618-183600-16842879-58874-20920-0000
> I0618 18:36:01.573529 20940 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: 9fbf7005-8849-4f61-9f9b-e973d730097a) for task 0 of framework 20140618-183600-16842879-58874-20920-0000 to master@127.0.1.1:58874
> I0618 18:36:01.573786 20940 master.cpp:3062] Status update TASK_RUNNING (UUID: 9fbf7005-8849-4f61-9f9b-e973d730097a) for task 0 of framework 20140618-183600-16842879-58874-20920-0000 from slave 20140618-183600-16842879-58874-20920-0 at slave(8)@127.0.1.1:58874 (lucid)
> I0618 18:36:01.574127 20940 master.cpp:610] Master terminating
> I0618 18:36:01.573859 20947 sched.cpp:637] Scheduler::statusUpdate took 17021ns
> I0618 18:36:01.574408 20940 master.hpp:775] Removing task 0 with resources cpus(*):1; mem(*):500 on slave 20140618-183600-16842879-58874-20920-0 (lucid)
> W0618 18:36:01.574589 20940 master.cpp:4209] Removing task 0 of framework 20140618-183600-16842879-58874-20920-0000 and slave 20140618-183600-16842879-58874-20920-0 in non-terminal state TASK_RUNNING
> I0618 18:36:01.574707 20944 hierarchical_allocator_process.hpp:635] Recovered cpus(*):1; mem(*):500 (total allocatable: cpus(*):2; mem(*):1024; disk(*):25759; ports(*):[31000-32000]) on slave 20140618-183600-16842879-58874-20920-0 from framework 20140618-183600-16842879-58874-20920-0000
> 2014-06-18 18:36:01,576:20920(0x2b89c8ff5120):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x146b1c427990001 to [127.0.0.1:57094]
> 2014-06-18 18:36:01,578:20920(0x2b89c8ff5120):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x146b1c427990000 to [127.0.0.1:57094]
> I0618 18:36:01.579398 20946 slave.cpp:2267] master@127.0.1.1:58874 exited
> W0618 18:36:01.579522 20946 slave.cpp:2270] Master disconnected! Waiting for a new master to be elected
> I0618 18:36:01.579638 20946 slave.cpp:2182] Status update manager successfully handled status update TASK_RUNNING (UUID: 9fbf7005-8849-4f61-9f9b-e973d730097a) for task 0 of framework 20140618-183600-16842879-58874-20920-0000
> I0618 18:36:01.579747 20946 slave.cpp:2188] Sending acknowledgement for status update TASK_RUNNING (UUID: 9fbf7005-8849-4f61-9f9b-e973d730097a) for task 0 of framework 20140618-183600-16842879-58874-20920-0000 to executor(2)@127.0.1.1:58874
> I0618 18:36:01.579915 20943 exec.cpp:338] Executor received status update acknowledgement 9fbf7005-8849-4f61-9f9b-e973d730097a for task 0 of framework 20140618-183600-16842879-58874-20920-0000
> I0618 18:36:01.594311 20942 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 28.596557ms
> I0618 18:36:01.594588 20942 replica.cpp:676] Persisted action at 4
> I0618 18:36:01.596770 20920 contender.cpp:186] Now cancelling the membership: 0
> 2014-06-18 18:36:01,596:20920(0x2b89c8ff5120):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x146b1c427990003 to [127.0.0.1:57094]
> 2014-06-18 18:36:01,597:20920(0x2b89c8ff5120):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x146b1c427990002 to [127.0.0.1:57094]
> I0618 18:36:01.618639 20944 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
> I0618 18:36:01.618701 20944 detector.cpp:126] The current leader (id=0) is lost
> I0618 18:36:01.618711 20944 detector.cpp:138] Detected a new leader: None
> I0618 18:36:01.618815 20944 slave.cpp:582] Lost leading master
> I0618 18:36:01.618824 20944 slave.cpp:586] Detecting new master
> I0618 18:36:01.619545 20947 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
> I0618 18:36:01.619593 20947 detector.cpp:126] The current leader (id=0) is lost
> I0618 18:36:01.619601 20947 detector.cpp:138] Detected a new leader: None
> I0618 18:36:01.619693 20947 sched.cpp:229] Scheduler::disconnected took 8171ns
> I0618 18:36:01.619704 20947 sched.cpp:251] No master detected
> I0618 18:36:01.671663 20920 leveldb.cpp:176] Opened db in 73.870317ms
> I0618 18:36:01.729127 20920 leveldb.cpp:183] Compacted db in 57.226645ms
> I0618 18:36:01.729398 20920 leveldb.cpp:198] Created db iterator in 9563ns
> I0618 18:36:01.729588 20920 leveldb.cpp:204] Seeked to beginning of db in 17071ns
> I0618 18:36:01.729789 20920 leveldb.cpp:273] Iterated through 5 keys in the db in 45850ns
> I0618 18:36:01.729964 20920 replica.cpp:741] Replica recovered with log positions 1 -> 4 with 0 holes and 1 unlearned
> 2014-06-18 18:36:01,730:20920(0x2b89c95f9700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
> 2014-06-18 18:36:01,730:20920(0x2b89c95f9700):ZOO_INFO@log_env@716: Client environment:host.name=lucid
> 2014-06-18 18:36:01,730:20920(0x2b89c95f9700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
> 2014-06-18 18:36:01,730:20920(0x2b89c95f9700):ZOO_INFO@log_env@724: Client environment:os.arch=2.6.32-61-generic
> 2014-06-18 18:36:01,730:20920(0x2b89c95f9700):ZOO_INFO@log_env@725: Client environment:os.version=#124-Ubuntu SMP Wed Jun 4 23:03:27 UTC 2014
> 2014-06-18 18:36:01,730:20920(0x2b89c95f9700):ZOO_INFO@log_env@733: Client environment:user.name=(null)
> 2014-06-18 18:36:01,730:20920(0x2b89c95f9700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
> 2014-06-18 18:36:01,730:20920(0x2b89c95f9700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_iCI9kS
> 2014-06-18 18:36:01,730:20920(0x2b89c95f9700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:57094 sessionTimeout=10000 watcher=0x2b89c40f5110 sessionId=0 sessionPasswd=<null> context=0x19b2f10 flags=0
> 2014-06-18 18:36:01,730:20920(0x2b89c9dfd700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
> 2014-06-18 18:36:01,731:20920(0x2b89c9dfd700):ZOO_INFO@log_env@716: Client environment:host.name=lucid
> 2014-06-18 18:36:01,731:20920(0x2b89c9dfd700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
> 2014-06-18 18:36:01,731:20920(0x2b89c9dfd700):ZOO_INFO@log_env@724: Client environment:os.arch=2.6.32-61-generic
> 2014-06-18 18:36:01,731:20920(0x2b89c9dfd700):ZOO_INFO@log_env@725: Client environment:os.version=#124-Ubuntu SMP Wed Jun 4 23:03:27 UTC 2014
> 2014-06-18 18:36:01,731:20920(0x2b89c9dfd700):ZOO_INFO@log_env@733: Client environment:user.name=(null)
> 2014-06-18 18:36:01,731:20920(0x2b89c9dfd700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
> 2014-06-18 18:36:01,731:20920(0x2b89c9dfd700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_iCI9kS
> 2014-06-18 18:36:01,731:20920(0x2b89c9dfd700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:57094 sessionTimeout=10000 watcher=0x2b89c40f5110 sessionId=0 sessionPasswd=<null> context=0x2b89cc2a4e00 flags=0
> I0618 18:36:01.731569 20945 log.cpp:238] Attempting to join replica to ZooKeeper group
> I0618 18:36:01.731704 20945 recover.cpp:425] Starting replica recovery
> I0618 18:36:01.731773 20945 recover.cpp:451] Replica is in VOTING status
> I0618 18:36:01.731811 20945 recover.cpp:440] Recover process terminated
> 2014-06-18 18:36:01,732:20920(0x2b89c91f7700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
> 2014-06-18 18:36:01,732:20920(0x2b89c91f7700):ZOO_INFO@log_env@716: Client environment:host.name=lucid
> 2014-06-18 18:36:01,732:20920(0x2b89c91f7700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
> 2014-06-18 18:36:01,732:20920(0x2b89c91f7700):ZOO_INFO@log_env@724: Client environment:os.arch=2.6.32-61-generic
> 2014-06-18 18:36:01,732:20920(0x2b89c91f7700):ZOO_INFO@log_env@725: Client environment:os.version=#124-Ubuntu SMP Wed Jun 4 23:03:27 UTC 2014
> 2014-06-18 18:36:01,732:20920(0x2b89c91f7700):ZOO_INFO@log_env@733: Client environment:user.name=(null)
> 2014-06-18 18:36:01,732:20920(0x2b89c91f7700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
> 2014-06-18 18:36:01,732:20920(0x2b89c91f7700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_iCI9kS
> 2014-06-18 18:36:01,732:20920(0x2b89c91f7700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:57094 sessionTimeout=10000 watcher=0x2b89c40f5110 sessionId=0 sessionPasswd=<null> context=0x19acef0 flags=0
> 2014-06-18 18:36:01,732:20920(0x2b89c9ffe700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
> 2014-06-18 18:36:01,732:20920(0x2b89c9ffe700):ZOO_INFO@log_env@716: Client environment:host.name=lucid
> 2014-06-18 18:36:01,732:20920(0x2b89c9ffe700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
> 2014-06-18 18:36:01,732:20920(0x2b89c9ffe700):ZOO_INFO@log_env@724: Client environment:os.arch=2.6.32-61-generic
> 2014-06-18 18:36:01,732:20920(0x2b89c9ffe700):ZOO_INFO@log_env@725: Client environment:os.version=#124-Ubuntu SMP Wed Jun 4 23:03:27 UTC 2014
> 2014-06-18 18:36:01,733:20920(0x2b89c9ffe700):ZOO_INFO@log_env@733: Client environment:user.name=(null)
> 2014-06-18 18:36:01,733:20920(0x2b89c9ffe700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
> 2014-06-18 18:36:01,733:20920(0x2b89c9ffe700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_iCI9kS
> 2014-06-18 18:36:01,733:20920(0x2b89c9ffe700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:57094 sessionTimeout=10000 watcher=0x2b89c40f5110 sessionId=0 sessionPasswd=<null> context=0x1896780 flags=0
> I0618 18:36:01.735405 20943 master.cpp:286] Master 20140618-183601-16842879-58874-20920 (lucid) started on 127.0.1.1:58874
> I0618 18:36:01.735426 20943 master.cpp:323] Master only allowing authenticated frameworks to register
> I0618 18:36:01.735432 20943 master.cpp:328] Master only allowing authenticated slaves to register
> I0618 18:36:01.735438 20943 credentials.hpp:35] Loading credentials for authentication from '/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_iCI9kS/credentials'
> I0618 18:36:01.735499 20943 master.cpp:354] Authorization enabled
> I0618 18:36:01.735944 20943 master.cpp:120] No whitelist given. Advertising offers for all slaves
> I0618 18:36:01.736229 20943 hierarchical_allocator_process.hpp:301] Initializing hierarchical allocator process with master : master@127.0.1.1:58874
> I0618 18:36:01.736274 20943 contender.cpp:131] Joining the ZK group
> 2014-06-18 18:36:01,739:20920(0x2b89d5861700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:57094]
> 2014-06-18 18:36:01,741:20920(0x2b89d5660700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:57094]
> 2014-06-18 18:36:01,743:20920(0x2b89d524a700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:57094]
> 2014-06-18 18:36:01,746:20920(0x2b89d5a62700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:57094]
> 2014-06-18 18:36:01,747:20920(0x2b89d5861700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:57094], sessionId=0x146b1c427990006, negotiated timeout=10000
> I0618 18:36:01.748674 20943 group.cpp:313] Group process (group(16)@127.0.1.1:58874) connected to ZooKeeper
> I0618 18:36:01.748695 20943 group.cpp:787] Syncing group operations: queue size (joins, cancels, datas) = (0, 0, 0)
> I0618 18:36:01.748703 20943 group.cpp:385] Trying to create path '/znode/log_replicas' in ZooKeeper
> 2014-06-18 18:36:01,758:20920(0x2b89d5660700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:57094], sessionId=0x146b1c427990007, negotiated timeout=10000
> I0618 18:36:01.758239 20945 group.cpp:313] Group process (group(18)@127.0.1.1:58874) connected to ZooKeeper
> I0618 18:36:01.758258 20945 group.cpp:787] Syncing group operations: queue size (joins, cancels, datas) = (1, 0, 0)
> I0618 18:36:01.758265 20945 group.cpp:385] Trying to create path '/znode' in ZooKeeper
> 2014-06-18 18:36:01,758:20920(0x2b89d524a700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:57094], sessionId=0x146b1c427990008, negotiated timeout=10000
> I0618 18:36:01.758652 20942 group.cpp:313] Group process (group(19)@127.0.1.1:58874) connected to ZooKeeper
> I0618 18:36:01.758668 20942 group.cpp:787] Syncing group operations: queue size (joins, cancels, datas) = (0, 0, 0)
> I0618 18:36:01.758676 20942 group.cpp:385] Trying to create path '/znode' in ZooKeeper
> 2014-06-18 18:36:01,769:20920(0x2b89d5a62700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:57094], sessionId=0x146b1c427990009, negotiated timeout=10000
> I0618 18:36:01.771797 20940 group.cpp:313] Group process (group(17)@127.0.1.1:58874) connected to ZooKeeper
> I0618 18:36:01.771818 20940 group.cpp:787] Syncing group operations: queue size (joins, cancels, datas) = (1, 0, 0)
> I0618 18:36:01.771827 20940 group.cpp:385] Trying to create path '/znode/log_replicas' in ZooKeeper
> I0618 18:36:01.789278 20941 contender.cpp:247] New candidate (id='2') has entered the contest for leadership
> I0618 18:36:01.790225 20942 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
> I0618 18:36:01.790303 20942 detector.cpp:138] Detected a new leader: (id='2')
> I0618 18:36:01.790441 20942 group.cpp:658] Trying to get '/znode/info_0000000002' in ZooKeeper
> I0618 18:36:01.792690 20943 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
> I0618 18:36:01.792745 20943 detector.cpp:138] Detected a new leader: (id='2')
> I0618 18:36:01.792835 20943 group.cpp:658] Trying to get '/znode/info_0000000002' in ZooKeeper
> I0618 18:36:01.793664 20946 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
> I0618 18:36:01.793720 20946 detector.cpp:138] Detected a new leader: (id='2')
> I0618 18:36:01.793800 20946 group.cpp:658] Trying to get '/znode/info_0000000002' in ZooKeeper
> I0618 18:36:01.794675 20945 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
> I0618 18:36:01.795300 20942 detector.cpp:382] A new leading master (UPID=master@127.0.1.1:58874) is detected
> I0618 18:36:01.795354 20942 master.cpp:1077] The newly elected leader is master@127.0.1.1:58874 with id 20140618-183601-16842879-58874-20920
> I0618 18:36:01.795367 20942 master.cpp:1090] Elected as the leading master!
> I0618 18:36:01.795372 20942 master.cpp:908] Recovering from registrar
> I0618 18:36:01.795431 20942 registrar.cpp:313] Recovering registrar
> I0618 18:36:01.795662 20942 log.cpp:656] Attempting to start the writer
> I0618 18:36:01.795964 20942 replica.cpp:474] Replica received implicit promise request with proposal 2
> I0618 18:36:01.796931 20944 network.hpp:423] ZooKeeper group memberships changed
> I0618 18:36:01.797011 20944 group.cpp:658] Trying to get '/znode/log_replicas/0000000001' in ZooKeeper
> I0618 18:36:01.798403 20943 detector.cpp:382] A new leading master (UPID=master@127.0.1.1:58874) is detected
> I0618 18:36:01.798461 20943 sched.cpp:235] New master detected at master@127.0.1.1:58874
> I0618 18:36:01.798476 20943 sched.cpp:285] Authenticating with master master@127.0.1.1:58874
> I0618 18:36:01.798558 20943 authenticatee.hpp:128] Creating new client SASL connection
> I0618 18:36:01.798624 20943 master.cpp:817] Dropping 'mesos.internal.AuthenticateMessage' message since not recovered yet
> I0618 18:36:01.799247 20946 detector.cpp:382] A new leading master (UPID=master@127.0.1.1:58874) is detected
> I0618 18:36:01.799301 20946 slave.cpp:537] New master detected at master@127.0.1.1:58874
> I0618 18:36:01.799321 20946 slave.cpp:613] Authenticating with master master@127.0.1.1:58874
> I0618 18:36:01.799357 20946 slave.cpp:586] Detecting new master
> I0618 18:36:01.799392 20946 status_update_manager.cpp:167] New master detected at master@127.0.1.1:58874
> W0618 18:36:01.799404 20946 status_update_manager.cpp:181] Resending status update TASK_RUNNING (UUID: 9fbf7005-8849-4f61-9f9b-e973d730097a) for task 0 of framework 20140618-183600-16842879-58874-20920-0000
> I0618 18:36:01.799417 20946 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: 9fbf7005-8849-4f61-9f9b-e973d730097a) for task 0 of framework 20140618-183600-16842879-58874-20920-0000 to master@127.0.1.1:58874
> I0618 18:36:01.799479 20946 authenticatee.hpp:128] Creating new client SASL connection
> I0618 18:36:01.799530 20946 master.cpp:817] Dropping 'mesos.internal.StatusUpdateMessage' message since not recovered yet
> I0618 18:36:01.799546 20946 master.cpp:817] Dropping 'mesos.internal.AuthenticateMessage' message since not recovered yet
> I0618 18:36:01.800221 20944 network.hpp:461] ZooKeeper group PIDs: { log-replica(92)@127.0.1.1:58874 }
> I0618 18:36:01.812145 20942 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 16.139525ms
> I0618 18:36:01.812326 20942 replica.cpp:342] Persisted promised to 2
> I0618 18:36:01.812573 20942 coordinator.cpp:230] Coordinator attemping to fill missing position
> I0618 18:36:01.812898 20942 replica.cpp:375] Replica received explicit promise request for position 4 with proposal 3
> I0618 18:36:01.812959 20942 leveldb.cpp:438] Reading position from leveldb took 45897ns
> I0618 18:36:01.832315 20942 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 19.327564ms
> I0618 18:36:01.832545 20942 replica.cpp:676] Persisted action at 4
> I0618 18:36:01.837110 20940 replica.cpp:508] Replica received write request for position 4
> I0618 18:36:01.837333 20940 leveldb.cpp:438] Reading position from leveldb took 21374ns
> I0618 18:36:01.856878 20940 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 19.358873ms
> I0618 18:36:01.857132 20940 replica.cpp:676] Persisted action at 4
> I0618 18:36:01.857520 20940 replica.cpp:655] Replica received learned notice for position 4
> I0618 18:36:01.873648 20940 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 15.865994ms
> I0618 18:36:01.873929 20940 leveldb.cpp:401] Deleting ~2 keys from leveldb took 39642ns
> I0618 18:36:01.874130 20940 replica.cpp:676] Persisted action at 4
> I0618 18:36:01.874321 20940 replica.cpp:661] Replica learned TRUNCATE action at position 4
> I0618 18:36:01.876976 20942 log.cpp:672] Writer started with ending position 4
> I0618 18:36:01.877259 20942 leveldb.cpp:438] Reading position from leveldb took 35330ns
> I0618 18:36:01.877286 20942 leveldb.cpp:438] Reading position from leveldb took 6414ns
> I0618 18:36:01.877627 20942 registrar.cpp:346] Successfully fetched the registry (250B)
> I0618 18:36:01.877653 20942 registrar.cpp:422] Attempting to update the 'registry'
> I0618 18:36:01.879057 20942 log.cpp:680] Attempting to append 289 bytes to the log
> I0618 18:36:01.879106 20942 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 5
> I0618 18:36:01.879319 20942 replica.cpp:508] Replica received write request for position 5
> I0618 18:36:01.899111 20942 leveldb.cpp:343] Persisting action (308 bytes) to leveldb took 19.759464ms
> I0618 18:36:01.899361 20942 replica.cpp:676] Persisted action at 5
> I0618 18:36:01.907029 20946 replica.cpp:655] Replica received learned notice for position 5
> I0618 18:36:01.929661 20946 leveldb.cpp:343] Persisting action (310 bytes) to leveldb took 22.596394ms
> I0618 18:36:01.929708 20946 replica.cpp:676] Persisted action at 5
> I0618 18:36:01.929718 20946 replica.cpp:661] Replica learned APPEND action at position 5
> I0618 18:36:01.930140 20946 registrar.cpp:479] Successfully updated 'registry'
> I0618 18:36:01.930201 20946 registrar.cpp:372] Successfully recovered registrar
> I0618 18:36:01.930277 20946 log.cpp:699] Attempting to truncate the log to 5
> I0618 18:36:01.930408 20946 master.cpp:935] Recovered 1 slaves from the Registry (250B) ; allowing 10mins for slaves to re-register
> I0618 18:36:01.930465 20946 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 6
> I0618 18:36:01.930938 20943 replica.cpp:508] Replica received write request for position 6
> I0618 18:36:01.949054 20943 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 18.077453ms
> I0618 18:36:01.949095 20943 replica.cpp:676] Persisted action at 6
> I0618 18:36:01.949306 20943 replica.cpp:655] Replica received learned notice for position 6
> I0618 18:36:01.971745 20943 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 22.413338ms
> I0618 18:36:01.972015 20943 leveldb.cpp:401] Deleting ~2 keys from leveldb took 49157ns
> I0618 18:36:01.972268 20943 replica.cpp:676] Persisted action at 6
> I0618 18:36:01.972487 20943 replica.cpp:661] Replica learned TRUNCATE action at position 6
> I0618 18:36:02.476902 21961 exec.cpp:85] Committing suicide by killing the process group
> I0618 18:36:02.477285 21946 exec.cpp:85] Committing suicide by killing the process group
> I0618 18:36:02.477468 21952 exec.cpp:85] Committing suicide by killing the process group
> I0618 18:36:02.736951 20944 hierarchical_allocator_process.hpp:724] No resources available to allocate!
> I0618 18:36:02.736986 20944 hierarchical_allocator_process.hpp:686] Performed allocation for 0 slaves in 71668ns
> I0618 18:36:03.746919 20947 hierarchical_allocator_process.hpp:724] No resources available to allocate!
> I0618 18:36:03.746955 20947 hierarchical_allocator_process.hpp:686] Performed allocation for 0 slaves in 96823ns
> I0618 18:36:04.757009 20944 hierarchical_allocator_process.hpp:724] No resources available to allocate!
> I0618 18:36:04.757060 20944 hierarchical_allocator_process.hpp:686] Performed allocation for 0 slaves in 71841ns
> I0618 18:36:05.766964 20946 hierarchical_allocator_process.hpp:724] No resources available to allocate!
> I0618 18:36:05.767014 20946 hierarchical_allocator_process.hpp:686] Performed allocation for 0 slaves in 74657ns
> I0618 18:36:06.736886 20944 master.cpp:120] No whitelist given. Advertising offers for all slaves
> I0618 18:36:06.777076 20940 hierarchical_allocator_process.hpp:724] No resources available to allocate!
> I0618 18:36:06.777114 20940 hierarchical_allocator_process.hpp:686] Performed allocation for 0 slaves in 148458ns
> W0618 18:36:06.807023 20942 sched.cpp:380] Authentication timed out
> I0618 18:36:06.807128 20942 sched.cpp:340] Failed to authenticate with master master@127.0.1.1:58874: Authentication discarded
> I0618 18:36:06.807162 20942 sched.cpp:285] Authenticating with master master@127.0.1.1:58874
> I0618 18:36:06.807241 20942 authenticatee.hpp:128] Creating new client SASL connection
> I0618 18:36:06.807342 20942 master.cpp:3457] Authenticating scheduler-1dd718fb-d1c6-459b-8ecd-b4a1974ea7f9@127.0.1.1:58874
> I0618 18:36:06.807432 20942 authenticator.hpp:156] Creating new server SASL connection
> I0618 18:36:06.807495 20942 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
> I0618 18:36:06.807509 20942 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0618 18:36:06.807533 20942 authenticator.hpp:262] Received SASL authentication start
> I0618 18:36:06.807585 20942 authenticator.hpp:384] Authentication requires more steps
> I0618 18:36:06.807611 20942 authenticatee.hpp:265] Received SASL authentication step
> I0618 18:36:06.807646 20942 authenticator.hpp:290] Received SASL authentication step
> I0618 18:36:06.807662 20942 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'lucid' server FQDN: 'lucid' SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0618 18:36:06.807668 20942 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
> I0618 18:36:06.807678 20942 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0618 18:36:06.807687 20942 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'lucid' server FQDN: 'lucid' SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0618 18:36:06.807693 20942 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0618 18:36:06.807698 20942 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0618 18:36:06.807708 20942 authenticator.hpp:376] Authentication success
> I0618 18:36:06.807734 20942 authenticatee.hpp:305] Authentication success
> I0618 18:36:06.807755 20942 master.cpp:3497] Successfully authenticated principal 'test-principal' at scheduler-1dd718fb-d1c6-459b-8ecd-b4a1974ea7f9@127.0.1.1:58874
> I0618 18:36:06.807824 20942 sched.cpp:359] Successfully authenticated with master master@127.0.1.1:58874
> I0618 18:36:06.807837 20942 sched.cpp:478] Sending registration request to master@127.0.1.1:58874
> I0618 18:36:06.807888 20942 master.cpp:1304] Received re-registration request from framework 20140618-183600-16842879-58874-20920-0000 at scheduler-1dd718fb-d1c6-459b-8ecd-b4a1974ea7f9@127.0.1.1:58874
> I0618 18:36:06.807910 20942 master.cpp:1156] Authorizing framework principal 'test-principal' to receive offers for role '*'
> I0618 18:36:06.808001 20942 master.cpp:1355] Re-registering framework 20140618-183600-16842879-58874-20920-0000 at scheduler-1dd718fb-d1c6-459b-8ecd-b4a1974ea7f9@127.0.1.1:58874
> I0618 18:36:06.808107 20942 sched.cpp:409] Framework registered with 20140618-183600-16842879-58874-20920-0000
> I0618 18:36:06.808130 20942 sched.cpp:423] Scheduler::registered took 9118ns
> I0618 18:36:06.808239 20942 hierarchical_allocator_process.hpp:331] Added framework 20140618-183600-16842879-58874-20920-0000
> I0618 18:36:06.808251 20942 hierarchical_allocator_process.hpp:724] No resources available to allocate!
> I0618 18:36:06.808256 20942 hierarchical_allocator_process.hpp:686] Performed allocation for 0 slaves in 6238ns
> W0618 18:36:06.808794 20946 slave.cpp:687] Authentication timed out
> W0618 18:36:06.808841 20946 slave.cpp:651] Failed to authenticate with master master@127.0.1.1:58874: Authentication discarded
> I0618 18:36:06.808863 20946 slave.cpp:613] Authenticating with master master@127.0.1.1:58874
> I0618 18:36:06.808908 20946 authenticatee.hpp:128] Creating new client SASL connection
> I0618 18:36:06.808958 20946 master.cpp:3457] Authenticating slave(8)@127.0.1.1:58874
> I0618 18:36:06.809018 20946 authenticator.hpp:156] Creating new server SASL connection
> I0618 18:36:06.809061 20946 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
> I0618 18:36:06.809072 20946 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0618 18:36:06.809087 20946 authenticator.hpp:262] Received SASL authentication start
> I0618 18:36:06.809115 20946 authenticator.hpp:384] Authentication requires more steps
> I0618 18:36:06.809131 20946 authenticatee.hpp:265] Received SASL authentication step
> I0618 18:36:06.809154 20946 authenticator.hpp:290] Received SASL authentication step
> I0618 18:36:06.809165 20946 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'lucid' server FQDN: 'lucid' SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0618 18:36:06.809171 20946 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
> I0618 18:36:06.809178 20946 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0618 18:36:06.809185 20946 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'lucid' server FQDN: 'lucid' SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0618 18:36:06.809190 20946 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0618 18:36:06.809195 20946 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0618 18:36:06.809205 20946 authenticator.hpp:376] Authentication success
> I0618 18:36:06.809221 20946 authenticatee.hpp:305] Authentication success
> I0618 18:36:06.809232 20946 master.cpp:3497] Successfully authenticated principal 'test-principal' at slave(8)@127.0.1.1:58874
> I0618 18:36:06.809278 20946 slave.cpp:670] Successfully authenticated with master master@127.0.1.1:58874
> I0618 18:36:06.809387 20946 slave.cpp:908] Will retry registration in 2.937598ms if necessary
> I0618 18:36:06.809483 20946 master.cpp:2911] Re-registering slave 20140618-183600-16842879-58874-20920-0 at slave(8)@127.0.1.1:58874 (lucid)
> I0618 18:36:06.809631 20946 registrar.cpp:422] Attempting to update the 'registry'
> I0618 18:36:06.811009 20946 log.cpp:680] Attempting to append 289 bytes to the log
> I0618 18:36:06.811059 20946 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 7
> I0618 18:36:06.811231 20946 replica.cpp:508] Replica received write request for position 7
> I0618 18:36:06.817005 20944 slave.cpp:908] Will retry registration in 29.446343ms if necessary
> I0618 18:36:06.817128 20944 master.cpp:2904] Ignoring re-register slave message from slave 20140618-183600-16842879-58874-20920-0 at slave(8)@127.0.1.1:58874 (lucid) as readmission is already in progress
> I0618 18:36:06.817399 20946 leveldb.cpp:343] Persisting action (308 bytes) to leveldb took 6.137907ms
> I0618 18:36:06.817746 20946 replica.cpp:676] Persisted action at 7
> I0618 18:36:06.827141 20940 replica.cpp:655] Replica received learned notice for position 7
> I0618 18:36:06.832229 20940 leveldb.cpp:343] Persisting action (310 bytes) to leveldb took 5.038965ms
> I0618 18:36:06.832275 20940 replica.cpp:676] Persisted action at 7
> I0618 18:36:06.832286 20940 replica.cpp:661] Replica learned APPEND action at position 7
> I0618 18:36:06.832638 20940 registrar.cpp:479] Successfully updated 'registry'
> I0618 18:36:06.832793 20940 log.cpp:699] Attempting to truncate the log to 7
> I0618 18:36:06.832851 20940 master.cpp:2962] Re-registered slave 20140618-183600-16842879-58874-20920-0 at slave(8)@127.0.1.1:58874 (lucid)
> I0618 18:36:06.832870 20940 master.cpp:3923] Adding slave 20140618-183600-16842879-58874-20920-0 at slave(8)@127.0.1.1:58874 (lucid) with cpus(*):2; mem(*):1024; disk(*):25759; ports(*):[31000-32000]
> I0618 18:36:06.833005 20940 master.hpp:757] Adding task 0 with resources cpus(*):1; mem(*):500 on slave 20140618-183600-16842879-58874-20920-0 (lucid)
> I0618 18:36:06.833137 20940 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 8
> I0618 18:36:06.833220 20940 slave.cpp:754] Re-registered with master master@127.0.1.1:58874
> I0618 18:36:06.833248 20940 slave.cpp:1520] Updating framework 20140618-183600-16842879-58874-20920-0000 pid to scheduler-1dd718fb-d1c6-459b-8ecd-b4a1974ea7f9@127.0.1.1:58874
> W0618 18:36:06.833418 20940 status_update_manager.cpp:181] Resending status update TASK_RUNNING (UUID: 9fbf7005-8849-4f61-9f9b-e973d730097a) for task 0 of framework 20140618-183600-16842879-58874-20920-0000
> I0618 18:36:06.833438 20940 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: 9fbf7005-8849-4f61-9f9b-e973d730097a) for task 0 of framework 20140618-183600-16842879-58874-20920-0000 to master@127.0.1.1:58874
> I0618 18:36:06.833542 20940 hierarchical_allocator_process.hpp:444] Added slave 20140618-183600-16842879-58874-20920-0 (lucid) with cpus(*):2; mem(*):1024; disk(*):25759; ports(*):[31000-32000] (and cpus(*):1; mem(*):524; disk(*):25759; ports(*):[31000-32000] available)
> I0618 18:36:06.833600 20940 hierarchical_allocator_process.hpp:750] Offering cpus(*):1; mem(*):524; disk(*):25759; ports(*):[31000-32000] on slave 20140618-183600-16842879-58874-20920-0 to framework 20140618-183600-16842879-58874-20920-0000
> I0618 18:36:06.833694 20940 hierarchical_allocator_process.hpp:706] Performed allocation for slave 20140618-183600-16842879-58874-20920-0 in 117966ns
> I0618 18:36:06.833786 20940 master.cpp:3062] Status update TASK_RUNNING (UUID: 9fbf7005-8849-4f61-9f9b-e973d730097a) for task 0 of framework 20140618-183600-16842879-58874-20920-0000 from slave 20140618-183600-16842879-58874-20920-0 at slave(8)@127.0.1.1:58874 (lucid)
> I0618 18:36:06.833853 20940 master.hpp:785] Adding offer 20140618-183601-16842879-58874-20920-0 with resources cpus(*):1; mem(*):524; disk(*):25759; ports(*):[31000-32000] on slave 20140618-183600-16842879-58874-20920-0 (lucid)
> I0618 18:36:06.833894 20940 master.cpp:3404] Sending 1 offers to framework 20140618-183600-16842879-58874-20920-0000
> tests/allocator_zookeeper_tests.cpp:105: Failure
> Mock function called more times than expected - returning directly.
> Function call: statusUpdate(0x7fffa8d7ce40, @0x190c6e0 80-byte object <F0-42 AC-C4 89-2B 00-00 00-00 00-00 00-00 00-00 B0-85 99-01 00-00 00-00 60-A1 FC-00 00-00 00-00 60-A1 FC-00 00-00 00-00 80-C7 9D-01 00-00 00-00 01-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 FF-93 E4-AA 8F-E8 D4-41 00-00 00-00 53-00 00-00>)
> Expected: to be called once
> Actual: called twice - over-saturated and active
> I0618 18:36:06.834125 20940 sched.cpp:637] Scheduler::statusUpdate took 147313ns
> I0618 18:36:06.834219 20940 sched.cpp:546] Scheduler::resourceOffers took 20752ns
> I0618 18:36:06.834308 20940 master.cpp:2586] Forwarding status update acknowledgement 9fbf7005-8849-4f61-9f9b-e973d730097a for task 0 of framework 20140618-183600-16842879-58874-20920-0000 to slave 20140618-183600-16842879-58874-20920-0 at slave(8)@127.0.1.1:58874 (lucid)
> I0618 18:36:06.834429 20947 replica.cpp:508] Replica received write request for position 8
> I0618 18:36:06.834547 20942 status_update_manager.cpp:398] Received status update acknowledgement (UUID: 9fbf7005-8849-4f61-9f9b-e973d730097a) for task 0 of framework 20140618-183600-16842879-58874-20920-0000
> I0618 18:36:06.834969 20942 slave.cpp:1610] Status update manager successfully handled status update acknowledgement (UUID: 9fbf7005-8849-4f61-9f9b-e973d730097a) for task 0 of framework 20140618-183600-16842879-58874-20920-0000
> I0618 18:36:06.835248 20920 master.cpp:610] Master terminating
> I0618 18:36:06.835297 20920 master.hpp:775] Removing task 0 with resources cpus(*):1; mem(*):500 on slave 20140618-183600-16842879-58874-20920-0 (lucid)
> W0618 18:36:06.835336 20920 master.cpp:4209] Removing task 0 of framework 20140618-183600-16842879-58874-20920-0000 and slave 20140618-183600-16842879-58874-20920-0 in non-terminal state TASK_RUNNING
> I0618 18:36:06.835372 20920 master.hpp:795] Removing offer 20140618-183601-16842879-58874-20920-0 with resources cpus(*):1; mem(*):524; disk(*):25759; ports(*):[31000-32000] on slave 20140618-183600-16842879-58874-20920-0 (lucid)
> 2014-06-18 18:36:06,836:20920(0x2b89c8ff5120):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x146b1c427990009 to [127.0.0.1:57094]
> I0618 18:36:06.836659 20942 sched.cpp:747] Stopping framework '20140618-183600-16842879-58874-20920-0000'
> I0618 18:36:06.836738 20942 slave.cpp:2267] master@127.0.1.1:58874 exited
> W0618 18:36:06.836753 20942 slave.cpp:2270] Master disconnected! Waiting for a new master to be elected
> I0618 18:36:06.839041 20947 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 4.533722ms
> I0618 18:36:06.839078 20947 replica.cpp:676] Persisted action at 8
> 2014-06-18 18:36:06,839:20920(0x2b89c8ff5120):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x146b1c427990006 to [127.0.0.1:57094]
> I0618 18:36:06.848645 20920 contender.cpp:186] Now cancelling the membership: 2
> 2014-06-18 18:36:06,849:20920(0x2b89c8ff5120):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x146b1c427990007 to [127.0.0.1:57094]
> 2014-06-18 18:36:06,850:20920(0x2b89c8ff5120):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x146b1c427990008 to [127.0.0.1:57094]
> I0618 18:36:06.850648 20920 slave.cpp:426] Slave terminating
> I0618 18:36:06.850678 20920 slave.cpp:1343] Asked to shut down framework 20140618-183600-16842879-58874-20920-0000 by @0.0.0.0:0
> I0618 18:36:06.850698 20920 slave.cpp:1368] Shutting down framework 20140618-183600-16842879-58874-20920-0000
> I0618 18:36:06.851362 20920 slave.cpp:2748] Shutting down executor 'default' of framework 20140618-183600-16842879-58874-20920-0000
> 2014-06-18 18:36:06,858:20920(0x2b89c8ff5120):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x146b1c427990004 to [127.0.0.1:57094]
> 2014-06-18 18:36:06,860:20920(0x2b89c8ff5120):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x146b1c427990005 to [127.0.0.1:57094]
> [ FAILED ] AllocatorZooKeeperTest/0.FrameworkReregistersFirst, where TypeParam = mesos::internal::master::allocator::HierarchicalAllocatorProcess<mesos::internal::master::allocator::DRFSorter, mesos::internal::master::allocator::DRFSorter> (5961 ms)
> {{noformat}}
--
This message was sent by Atlassian JIRA
(v6.2#6252)