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 22:50:25 UTC
[jira] [Assigned] (MESOS-1532)
AllocatorZooKeeperTest/0.SlaveReregistersFirst and
AllocatorZooKeeperTest/0.FrameworkReregistersFirst are flaky
[ https://issues.apache.org/jira/browse/MESOS-1532?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Vinod Kone reassigned MESOS-1532:
---------------------------------
Assignee: Vinod Kone
> AllocatorZooKeeperTest/0.SlaveReregistersFirst and AllocatorZooKeeperTest/0.FrameworkReregistersFirst are flaky
> ---------------------------------------------------------------------------------------------------------------
>
> Key: MESOS-1532
> URL: https://issues.apache.org/jira/browse/MESOS-1532
> Project: Mesos
> Issue Type: Bug
> Components: test
> Affects Versions: 0.20.0
> Reporter: Yan Xu
> Assignee: Vinod Kone
>
> {noformat:title=error AllocatorZooKeeperTest/0.SlaveReregistersFirst}
> tests/allocator_zookeeper_tests.cpp:220: Failure
> Mock function called more times than expected - returning directly.
> Function call: statusUpdate(0x7fff02ad01e0, @0x2b8494012130 80-byte object <60-CE A1-76 84-2B 00-00 00-00 00-00 00-00 00-00 E0-80 00-94 84-2B 00-00 48-B0 20-01 00-00 00-00 48-B0 20-01 00-00 00-00 E0-CF 01-94 84-2B 00-00 01-00 00-00 00-43 75-72 00-00 00-00 00-00 00-00 DD-0A D8-52 43-E9 D4-41 00-00 00-00 53-00 00-00>)
> Expected: to be called once
> Actual: called twice - over-saturated and active
> {noformat}
> {noformat:title=error AllocatorZooKeeperTest/0.FrameworkReregistersFirst}
> tests/allocator_zookeeper_tests.cpp:105: Failure
> Mock function called more times than expected - returning directly.
> Function call: statusUpdate(0x7fff498ab9c0, @0x2b2864099960 80-byte object <10-3D 7A-44 28-2B 00-00 00-00 00-00 00-00 00-00 D0-74 09-64 28-2B 00-00 38-E1 EC-00 00-00 00-00 38-E1 EC-00 00-00 00-00 50-89 06-64 28-2B 00-00 01-00 00-00 00-2B 00-00 00-00 00-00 00-00 00-00 B8-B1 4F-3C 45-E9 D4-41 00-00 00-00 53-00 00-00>)
> Expected: to be called once
> Actual: called twice - over-saturated and active
> {noformat}
> {noformat:title=full log AllocatorZooKeeperTest/0.SlaveReregistersFirst}
> [ RUN ] AllocatorZooKeeperTest/0.SlaveReregistersFirst
> Using temporary directory '/tmp/AllocatorZooKeeperTest_0_SlaveReregistersFirst_aWAV8S'
> I0620 21:42:45.231919 20363 leveldb.cpp:176] Opened db in 3.699122ms
> I0620 21:42:45.233388 20363 leveldb.cpp:183] Compacted db in 1.103569ms
> I0620 21:42:45.233770 20363 leveldb.cpp:198] Created db iterator in 17557ns
> I0620 21:42:45.234055 20363 leveldb.cpp:204] Seeked to beginning of db in 13726ns
> I0620 21:42:45.234341 20363 leveldb.cpp:273] Iterated through 0 keys in the db in 13396ns
> I0620 21:42:45.234617 20363 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
> 2014-06-20 21:42:45,235:20363(0x2b847d3e0700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
> 2014-06-20 21:42:45,235:20363(0x2b847d3e0700):ZOO_INFO@log_env@716: Client environment:host.name=saucy
> 2014-06-20 21:42:45,235:20363(0x2b847d3e0700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
> 2014-06-20 21:42:45,235:20363(0x2b847d3e0700):ZOO_INFO@log_env@724: Client environment:os.arch=3.11.0-23-generic
> 2014-06-20 21:42:45,235:20363(0x2b847d3e0700):ZOO_INFO@log_env@725: Client environment:os.version=#40-Ubuntu SMP Wed Jun 4 21:05:23 UTC 2014
> 2014-06-20 21:42:45,235:20363(0x2b847d3e0700):ZOO_INFO@log_env@733: Client environment:user.name=jenkins
> 2014-06-20 21:42:45,235:20363(0x2b847d3e0700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
> 2014-06-20 21:42:45,235:20363(0x2b847d3e0700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/AllocatorZooKeeperTest_0_SlaveReregistersFirst_aWAV8S
> 2014-06-20 21:42:45,235:20363(0x2b847d3e0700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:40498 sessionTimeout=10000 watcher=0x2b8476040110 sessionId=0 sessionPasswd=<null> context=0x2b84900103d0 flags=0
> 2014-06-20 21:42:45,235:20363(0x2b847d7e2700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
> 2014-06-20 21:42:45,235:20363(0x2b847d7e2700):ZOO_INFO@log_env@716: Client environment:host.name=saucy
> 2014-06-20 21:42:45,235:20363(0x2b847d7e2700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
> 2014-06-20 21:42:45,235:20363(0x2b847d7e2700):ZOO_INFO@log_env@724: Client environment:os.arch=3.11.0-23-generic
> 2014-06-20 21:42:45,236:20363(0x2b847d7e2700):ZOO_INFO@log_env@725: Client environment:os.version=#40-Ubuntu SMP Wed Jun 4 21:05:23 UTC 2014
> 2014-06-20 21:42:45,236:20363(0x2b847d7e2700):ZOO_INFO@log_env@733: Client environment:user.name=jenkins
> 2014-06-20 21:42:45,236:20363(0x2b847d7e2700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
> 2014-06-20 21:42:45,236:20363(0x2b847d7e2700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/AllocatorZooKeeperTest_0_SlaveReregistersFirst_aWAV8S
> 2014-06-20 21:42:45,236:20363(0x2b847d7e2700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:40498 sessionTimeout=10000 watcher=0x2b8476040110 sessionId=0 sessionPasswd=<null> context=0x2b848c01bec0 flags=0
> I0620 21:42:45.236599 20388 log.cpp:238] Attempting to join replica to ZooKeeper group
> I0620 21:42:45.236737 20388 recover.cpp:425] Starting replica recovery
> I0620 21:42:45.236809 20388 recover.cpp:451] Replica is in EMPTY status
> I0620 21:42:45.237169 20388 replica.cpp:638] Replica in EMPTY status received a broadcasted recover request
> I0620 21:42:45.237231 20388 recover.cpp:188] Received a recover response from a replica in EMPTY status
> I0620 21:42:45.237334 20388 recover.cpp:542] Updating replica status to STARTING
> I0620 21:42:45.238358 20388 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 972956ns
> I0620 21:42:45.238378 20388 replica.cpp:320] Persisted replica status to STARTING
> I0620 21:42:45.238435 20388 recover.cpp:451] Replica is in STARTING status
> I0620 21:42:45.238689 20388 replica.cpp:638] Replica in STARTING status received a broadcasted recover request
> I0620 21:42:45.238797 20382 recover.cpp:188] Received a recover response from a replica in STARTING status
> I0620 21:42:45.238881 20382 recover.cpp:542] Updating replica status to VOTING
> I0620 21:42:45.239800 20382 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 842002ns
> I0620 21:42:45.239820 20382 replica.cpp:320] Persisted replica status to VOTING
> I0620 21:42:45.239980 20382 recover.cpp:556] Successfully joined the Paxos group
> I0620 21:42:45.240031 20382 recover.cpp:440] Recover process terminated
> 2014-06-20 21:42:45,240:20363(0x2b847d1df700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
> 2014-06-20 21:42:45,240:20363(0x2b847d1df700):ZOO_INFO@log_env@716: Client environment:host.name=saucy
> 2014-06-20 21:42:45,240:20363(0x2b847d1df700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
> 2014-06-20 21:42:45,240:20363(0x2b847d1df700):ZOO_INFO@log_env@724: Client environment:os.arch=3.11.0-23-generic
> 2014-06-20 21:42:45,240:20363(0x2b847d1df700):ZOO_INFO@log_env@725: Client environment:os.version=#40-Ubuntu SMP Wed Jun 4 21:05:23 UTC 2014
> 2014-06-20 21:42:45,240:20363(0x2b847d1df700):ZOO_INFO@log_env@733: Client environment:user.name=jenkins
> 2014-06-20 21:42:45,240:20363(0x2b847d1df700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
> 2014-06-20 21:42:45,240:20363(0x2b847d1df700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/AllocatorZooKeeperTest_0_SlaveReregistersFirst_aWAV8S
> 2014-06-20 21:42:45,240:20363(0x2b847d1df700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:40498 sessionTimeout=10000 watcher=0x2b8476040110 sessionId=0 sessionPasswd=<null> context=0x2b849c014310 flags=0
> 2014-06-20 21:42:45,240:20363(0x2b847d9e3700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
> 2014-06-20 21:42:45,240:20363(0x2b847d9e3700):ZOO_INFO@log_env@716: Client environment:host.name=saucy
> 2014-06-20 21:42:45,240:20363(0x2b847d9e3700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
> 2014-06-20 21:42:45,240:20363(0x2b847d9e3700):ZOO_INFO@log_env@724: Client environment:os.arch=3.11.0-23-generic
> 2014-06-20 21:42:45,240:20363(0x2b847d9e3700):ZOO_INFO@log_env@725: Client environment:os.version=#40-Ubuntu SMP Wed Jun 4 21:05:23 UTC 2014
> 2014-06-20 21:42:45,240:20363(0x2b847d9e3700):ZOO_INFO@log_env@733: Client environment:user.name=jenkins
> 2014-06-20 21:42:45,240:20363(0x2b847d9e3700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
> 2014-06-20 21:42:45,240:20363(0x2b847d9e3700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/AllocatorZooKeeperTest_0_SlaveReregistersFirst_aWAV8S
> 2014-06-20 21:42:45,240:20363(0x2b847d9e3700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:40498 sessionTimeout=10000 watcher=0x2b8476040110 sessionId=0 sessionPasswd=<null> context=0x2b849c00bed0 flags=0
> I0620 21:42:45.242362 20387 master.cpp:286] Master 20140620-214245-16842879-38275-20363 (saucy) started on 127.0.1.1:38275
> I0620 21:42:45.242395 20387 master.cpp:323] Master only allowing authenticated frameworks to register
> I0620 21:42:45.242401 20387 master.cpp:328] Master only allowing authenticated slaves to register
> I0620 21:42:45.242408 20387 credentials.hpp:35] Loading credentials for authentication from '/tmp/AllocatorZooKeeperTest_0_SlaveReregistersFirst_aWAV8S/credentials'
> I0620 21:42:45.242482 20387 master.cpp:354] Authorization enabled
> I0620 21:42:45.243221 20387 hierarchical_allocator_process.hpp:301] Initializing hierarchical allocator process with master : master@127.0.1.1:38275
> I0620 21:42:45.243310 20387 master.cpp:120] No whitelist given. Advertising offers for all slaves
> I0620 21:42:45.243505 20387 contender.cpp:131] Joining the ZK group
> 2014-06-20 21:42:45,245:20363(0x2b84a835c700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:40498]
> 2014-06-20 21:42:45,249:20363(0x2b84a835c700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:40498], sessionId=0x146bcbbc114000a, negotiated timeout=10000
> I0620 21:42:45.252074 20388 group.cpp:313] Group process (group(12)@127.0.1.1:38275) connected to ZooKeeper
> I0620 21:42:45.252099 20388 group.cpp:787] Syncing group operations: queue size (joins, cancels, datas) = (1, 0, 0)
> I0620 21:42:45.252107 20388 group.cpp:385] Trying to create path '/znode/log_replicas' in ZooKeeper
> 2014-06-20 21:42:45,255:20363(0x2b84a7545700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:40498]
> 2014-06-20 21:42:45,255:20363(0x2b84a7545700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:40498], sessionId=0x146bcbbc114000b, negotiated timeout=10000
> I0620 21:42:45.257016 20387 group.cpp:313] Group process (group(13)@127.0.1.1:38275) connected to ZooKeeper
> I0620 21:42:45.257037 20387 group.cpp:787] Syncing group operations: queue size (joins, cancels, datas) = (1, 0, 0)
> I0620 21:42:45.257045 20387 group.cpp:385] Trying to create path '/znode' in ZooKeeper
> 2014-06-20 21:42:45,257:20363(0x2b84a7143700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:40498]
> 2014-06-20 21:42:45,257:20363(0x2b84a7143700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:40498], sessionId=0x146bcbbc114000c, negotiated timeout=10000
> I0620 21:42:45.257833 20386 group.cpp:313] Group process (group(14)@127.0.1.1:38275) connected to ZooKeeper
> I0620 21:42:45.257853 20386 group.cpp:787] Syncing group operations: queue size (joins, cancels, datas) = (0, 0, 0)
> I0620 21:42:45.257859 20386 group.cpp:385] Trying to create path '/znode' in ZooKeeper
> 2014-06-20 21:42:45,258:20363(0x2b84a875e700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:40498]
> 2014-06-20 21:42:45,266:20363(0x2b84a875e700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:40498], sessionId=0x146bcbbc114000d, negotiated timeout=10000
> I0620 21:42:45.268331 20381 group.cpp:313] Group process (group(11)@127.0.1.1:38275) connected to ZooKeeper
> I0620 21:42:45.268357 20381 group.cpp:787] Syncing group operations: queue size (joins, cancels, datas) = (0, 0, 0)
> I0620 21:42:45.268364 20381 group.cpp:385] Trying to create path '/znode/log_replicas' in ZooKeeper
> I0620 21:42:45.277688 20382 contender.cpp:247] New candidate (id='3') has entered the contest for leadership
> I0620 21:42:45.279588 20381 network.hpp:423] ZooKeeper group memberships changed
> I0620 21:42:45.279690 20381 group.cpp:658] Trying to get '/znode/log_replicas/0000000002' in ZooKeeper
> I0620 21:42:45.280855 20386 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
> I0620 21:42:45.280936 20386 detector.cpp:138] Detected a new leader: (id='3')
> I0620 21:42:45.281072 20386 group.cpp:658] Trying to get '/znode/info_0000000003' in ZooKeeper
> I0620 21:42:45.282238 20387 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
> I0620 21:42:45.283659 20381 network.hpp:461] ZooKeeper group PIDs: { log-replica(13)@127.0.1.1:38275 }
> I0620 21:42:45.284572 20386 detector.cpp:382] A new leading master (UPID=master@127.0.1.1:38275) is detected
> I0620 21:42:45.284644 20386 master.cpp:1077] The newly elected leader is master@127.0.1.1:38275 with id 20140620-214245-16842879-38275-20363
> I0620 21:42:45.284659 20386 master.cpp:1090] Elected as the leading master!
> I0620 21:42:45.284665 20386 master.cpp:908] Recovering from registrar
> I0620 21:42:45.284729 20386 registrar.cpp:313] Recovering registrar
> I0620 21:42:45.285032 20386 log.cpp:656] Attempting to start the writer
> I0620 21:42:45.285352 20386 replica.cpp:474] Replica received implicit promise request with proposal 1
> I0620 21:42:45.286321 20386 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 963603ns
> I0620 21:42:45.286345 20386 replica.cpp:342] Persisted promised to 1
> I0620 21:42:45.286509 20386 coordinator.cpp:230] Coordinator attemping to fill missing position
> I0620 21:42:45.286841 20386 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2
> I0620 21:42:45.287547 20386 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 699305ns
> I0620 21:42:45.287874 20386 replica.cpp:676] Persisted action at 0
> I0620 21:42:45.293628 20381 replica.cpp:508] Replica received write request for position 0
> I0620 21:42:45.293664 20381 leveldb.cpp:438] Reading position from leveldb took 20557ns
> I0620 21:42:45.294767 20381 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 1.098922ms
> I0620 21:42:45.294801 20381 replica.cpp:676] Persisted action at 0
> I0620 21:42:45.294973 20381 replica.cpp:655] Replica received learned notice for position 0
> I0620 21:42:45.295692 20381 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 713205ns
> I0620 21:42:45.295712 20381 replica.cpp:676] Persisted action at 0
> I0620 21:42:45.295719 20381 replica.cpp:661] Replica learned NOP action at position 0
> I0620 21:42:45.295871 20381 log.cpp:672] Writer started with ending position 0
> I0620 21:42:45.296139 20381 leveldb.cpp:438] Reading position from leveldb took 19864ns
> I0620 21:42:45.302870 20381 registrar.cpp:346] Successfully fetched the registry (0B)
> I0620 21:42:45.302898 20381 registrar.cpp:422] Attempting to update the 'registry'
> I0620 21:42:45.304384 20383 log.cpp:680] Attempting to append 118 bytes to the log
> I0620 21:42:45.304433 20383 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1
> I0620 21:42:45.304612 20383 replica.cpp:508] Replica received write request for position 1
> I0620 21:42:45.305519 20383 leveldb.cpp:343] Persisting action (135 bytes) to leveldb took 899961ns
> I0620 21:42:45.305541 20383 replica.cpp:676] Persisted action at 1
> I0620 21:42:45.305698 20383 replica.cpp:655] Replica received learned notice for position 1
> I0620 21:42:45.306144 20383 leveldb.cpp:343] Persisting action (137 bytes) to leveldb took 442506ns
> I0620 21:42:45.306164 20383 replica.cpp:676] Persisted action at 1
> I0620 21:42:45.306171 20383 replica.cpp:661] Replica learned APPEND action at position 1
> I0620 21:42:45.306416 20383 registrar.cpp:479] Successfully updated 'registry'
> I0620 21:42:45.306449 20383 registrar.cpp:372] Successfully recovered registrar
> I0620 21:42:45.306481 20383 log.cpp:699] Attempting to truncate the log to 1
> I0620 21:42:45.306541 20383 master.cpp:935] Recovered 0 slaves from the Registry (82B) ; allowing 10mins for slaves to re-register
> I0620 21:42:45.306581 20383 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2
> I0620 21:42:45.307407 20383 replica.cpp:508] Replica received write request for position 2
> I0620 21:42:45.310607 20381 slave.cpp:165] Slave started on 13)@127.0.1.1:38275
> 2014-06-20 21:42:45,310:20363(0x2b847d5e1700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
> I0620 21:42:45.311226 20381 credentials.hpp:35] Loading credentials for authentication from '/tmp/AllocatorZooKeeperTest_0_SlaveReregistersFirst_J7cnya/credential'
> I0620 21:42:45.312001 20381 slave.cpp:265] Slave using credential for: test-principal
> I0620 21:42:45.312470 20381 slave.cpp:278] Slave resources: cpus(*):2; mem(*):1024; disk(*):24988; ports(*):[31000-32000]
> 2014-06-20 21:42:45,311:20363(0x2b847d5e1700):ZOO_INFO@log_env@716: Client environment:host.name=saucy
> 2014-06-20 21:42:45,312:20363(0x2b847d5e1700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
> 2014-06-20 21:42:45,312:20363(0x2b847d5e1700):ZOO_INFO@log_env@724: Client environment:os.arch=3.11.0-23-generic
> 2014-06-20 21:42:45,312:20363(0x2b847d5e1700):ZOO_INFO@log_env@725: Client environment:os.version=#40-Ubuntu SMP Wed Jun 4 21:05:23 UTC 2014
> 2014-06-20 21:42:45,312:20363(0x2b847d5e1700):ZOO_INFO@log_env@733: Client environment:user.name=jenkins
> 2014-06-20 21:42:45,312:20363(0x2b847d5e1700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
> 2014-06-20 21:42:45,312:20363(0x2b847d5e1700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/AllocatorZooKeeperTest_0_SlaveReregistersFirst_aWAV8S
> 2014-06-20 21:42:45,313:20363(0x2b847d5e1700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:40498 sessionTimeout=10000 watcher=0x2b8476040110 sessionId=0 sessionPasswd=<null> context=0x2b849400a950 flags=0
> I0620 21:42:45.313387 20381 slave.cpp:306] Slave hostname: saucy
> I0620 21:42:45.313648 20381 slave.cpp:307] Slave checkpoint: false
> I0620 21:42:45.311570 20383 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 1.531355ms
> I0620 21:42:45.314107 20383 replica.cpp:676] Persisted action at 2
> I0620 21:42:45.318411 20388 replica.cpp:655] Replica received learned notice for position 2
> I0620 21:42:45.319124 20388 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 702563ns
> I0620 21:42:45.319166 20388 leveldb.cpp:401] Deleting ~1 keys from leveldb took 28762ns
> I0620 21:42:45.319178 20388 replica.cpp:676] Persisted action at 2
> I0620 21:42:45.319185 20388 replica.cpp:661] Replica learned TRUNCATE action at position 2
> I0620 21:42:45.319700 20381 state.cpp:33] Recovering state from '/tmp/AllocatorZooKeeperTest_0_SlaveReregistersFirst_J7cnya/meta'
> I0620 21:42:45.320158 20381 status_update_manager.cpp:193] Recovering status update manager
> 2014-06-20 21:42:45,320:20363(0x2b847dde5700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
> 2014-06-20 21:42:45,320:20363(0x2b847dde5700):ZOO_INFO@log_env@716: Client environment:host.name=saucy
> 2014-06-20 21:42:45,320:20363(0x2b847dde5700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
> 2014-06-20 21:42:45,320:20363(0x2b847dde5700):ZOO_INFO@log_env@724: Client environment:os.arch=3.11.0-23-generic
> 2014-06-20 21:42:45,320:20363(0x2b847dde5700):ZOO_INFO@log_env@725: Client environment:os.version=#40-Ubuntu SMP Wed Jun 4 21:05:23 UTC 2014
> 2014-06-20 21:42:45,320:20363(0x2b847dde5700):ZOO_INFO@log_env@733: Client environment:user.name=jenkins
> 2014-06-20 21:42:45,320:20363(0x2b847dde5700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
> 2014-06-20 21:42:45,320:20363(0x2b847dde5700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/AllocatorZooKeeperTest_0_SlaveReregistersFirst_aWAV8S
> 2014-06-20 21:42:45,320:20363(0x2b847dde5700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:40498 sessionTimeout=10000 watcher=0x2b8476040110 sessionId=0 sessionPasswd=<null> context=0x2b848800aba0 flags=0
> I0620 21:42:45.321244 20386 slave.cpp:3112] Finished recovery
> I0620 21:42:45.321732 20363 sched.cpp:139] Version: 0.20.0
> 2014-06-20 21:42:45,323:20363(0x2b84a7d59700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:40498]
> 2014-06-20 21:42:45,328:20363(0x2b84a7d59700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:40498], sessionId=0x146bcbbc114000e, negotiated timeout=10000
> I0620 21:42:45.331316 20383 group.cpp:313] Group process (group(15)@127.0.1.1:38275) connected to ZooKeeper
> I0620 21:42:45.331338 20383 group.cpp:787] Syncing group operations: queue size (joins, cancels, datas) = (0, 0, 0)
> I0620 21:42:45.331346 20383 group.cpp:385] Trying to create path '/znode' in ZooKeeper
> 2014-06-20 21:42:45,328:20363(0x2b84a7957700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:40498]
> 2014-06-20 21:42:45,331:20363(0x2b84a7957700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:40498], sessionId=0x146bcbbc114000f, negotiated timeout=10000
> I0620 21:42:45.331938 20384 group.cpp:313] Group process (group(16)@127.0.1.1:38275) connected to ZooKeeper
> I0620 21:42:45.331964 20384 group.cpp:787] Syncing group operations: queue size (joins, cancels, datas) = (0, 0, 0)
> I0620 21:42:45.331970 20384 group.cpp:385] Trying to create path '/znode' in ZooKeeper
> I0620 21:42:45.340384 20383 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
> I0620 21:42:45.340442 20383 detector.cpp:138] Detected a new leader: (id='3')
> I0620 21:42:45.340544 20383 group.cpp:658] Trying to get '/znode/info_0000000003' in ZooKeeper
> I0620 21:42:45.346941 20384 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
> I0620 21:42:45.347008 20384 detector.cpp:138] Detected a new leader: (id='3')
> I0620 21:42:45.347113 20384 group.cpp:658] Trying to get '/znode/info_0000000003' in ZooKeeper
> I0620 21:42:45.347441 20383 detector.cpp:382] A new leading master (UPID=master@127.0.1.1:38275) is detected
> I0620 21:42:45.347532 20383 slave.cpp:581] New master detected at master@127.0.1.1:38275
> I0620 21:42:45.347555 20383 slave.cpp:657] Authenticating with master master@127.0.1.1:38275
> I0620 21:42:45.347597 20383 slave.cpp:630] Detecting new master
> I0620 21:42:45.347631 20383 status_update_manager.cpp:167] New master detected at master@127.0.1.1:38275
> I0620 21:42:45.347664 20383 authenticatee.hpp:128] Creating new client SASL connection
> I0620 21:42:45.347888 20383 master.cpp:3457] Authenticating slave(13)@127.0.1.1:38275
> I0620 21:42:45.348104 20383 authenticator.hpp:156] Creating new server SASL connection
> I0620 21:42:45.348214 20383 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
> I0620 21:42:45.348237 20383 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0620 21:42:45.348258 20383 authenticator.hpp:262] Received SASL authentication start
> I0620 21:42:45.348304 20383 authenticator.hpp:384] Authentication requires more steps
> I0620 21:42:45.348328 20383 authenticatee.hpp:265] Received SASL authentication step
> I0620 21:42:45.348361 20383 authenticator.hpp:290] Received SASL authentication step
> I0620 21:42:45.348376 20383 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'saucy' server FQDN: 'saucy' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0620 21:42:45.348382 20383 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
> I0620 21:42:45.348394 20383 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0620 21:42:45.348402 20383 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'saucy' server FQDN: 'saucy' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0620 21:42:45.348408 20383 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0620 21:42:45.348413 20383 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0620 21:42:45.348424 20383 authenticator.hpp:376] Authentication success
> I0620 21:42:45.348446 20383 authenticatee.hpp:305] Authentication success
> I0620 21:42:45.348466 20383 master.cpp:3497] Successfully authenticated principal 'test-principal' at slave(13)@127.0.1.1:38275
> I0620 21:42:45.348530 20383 slave.cpp:714] Successfully authenticated with master master@127.0.1.1:38275
> I0620 21:42:45.348566 20383 slave.cpp:952] Will retry registration in 15.607002ms if necessary
> I0620 21:42:45.348664 20383 master.cpp:2736] Registering slave at slave(13)@127.0.1.1:38275 (saucy) with id 20140620-214245-16842879-38275-20363-0
> I0620 21:42:45.348752 20383 registrar.cpp:422] Attempting to update the 'registry'
> I0620 21:42:45.350170 20383 log.cpp:680] Attempting to append 289 bytes to the log
> I0620 21:42:45.350235 20383 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3
> I0620 21:42:45.350458 20383 replica.cpp:508] Replica received write request for position 3
> I0620 21:42:45.354960 20384 detector.cpp:382] A new leading master (UPID=master@127.0.1.1:38275) is detected
> I0620 21:42:45.355164 20384 sched.cpp:235] New master detected at master@127.0.1.1:38275
> I0620 21:42:45.355182 20384 sched.cpp:285] Authenticating with master master@127.0.1.1:38275
> I0620 21:42:45.355284 20384 authenticatee.hpp:128] Creating new client SASL connection
> I0620 21:42:45.355448 20384 master.cpp:3457] Authenticating scheduler-b20a9ea5-51ce-43ec-b8b9-e9c0e95af495@127.0.1.1:38275
> I0620 21:42:45.355523 20384 authenticator.hpp:156] Creating new server SASL connection
> I0620 21:42:45.355617 20384 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
> I0620 21:42:45.355634 20384 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0620 21:42:45.355654 20384 authenticator.hpp:262] Received SASL authentication start
> I0620 21:42:45.355687 20384 authenticator.hpp:384] Authentication requires more steps
> I0620 21:42:45.355710 20384 authenticatee.hpp:265] Received SASL authentication step
> I0620 21:42:45.355736 20384 authenticator.hpp:290] Received SASL authentication step
> I0620 21:42:45.355748 20384 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'saucy' server FQDN: 'saucy' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0620 21:42:45.355756 20384 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
> I0620 21:42:45.355764 20384 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0620 21:42:45.355772 20384 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'saucy' server FQDN: 'saucy' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0620 21:42:45.355778 20384 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0620 21:42:45.355782 20384 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0620 21:42:45.355792 20384 authenticator.hpp:376] Authentication success
> I0620 21:42:45.355813 20384 authenticatee.hpp:305] Authentication success
> I0620 21:42:45.355831 20384 master.cpp:3497] Successfully authenticated principal 'test-principal' at scheduler-b20a9ea5-51ce-43ec-b8b9-e9c0e95af495@127.0.1.1:38275
> I0620 21:42:45.355904 20384 sched.cpp:359] Successfully authenticated with master master@127.0.1.1:38275
> I0620 21:42:45.355960 20384 sched.cpp:478] Sending registration request to master@127.0.1.1:38275
> I0620 21:42:45.356015 20384 master.cpp:1196] Received registration request from scheduler-b20a9ea5-51ce-43ec-b8b9-e9c0e95af495@127.0.1.1:38275
> I0620 21:42:45.356030 20384 master.cpp:1156] Authorizing framework principal 'test-principal' to receive offers for role '*'
> I0620 21:42:45.356124 20384 master.cpp:1255] Registering framework 20140620-214245-16842879-38275-20363-0000 at scheduler-b20a9ea5-51ce-43ec-b8b9-e9c0e95af495@127.0.1.1:38275
> I0620 21:42:45.356204 20384 sched.cpp:409] Framework registered with 20140620-214245-16842879-38275-20363-0000
> I0620 21:42:45.356225 20384 sched.cpp:423] Scheduler::registered took 12192ns
> I0620 21:42:45.356257 20384 hierarchical_allocator_process.hpp:331] Added framework 20140620-214245-16842879-38275-20363-0000
> I0620 21:42:45.356266 20384 hierarchical_allocator_process.hpp:724] No resources available to allocate!
> I0620 21:42:45.356271 20384 hierarchical_allocator_process.hpp:686] Performed allocation for 0 slaves in 8900ns
> I0620 21:42:45.356500 20383 leveldb.cpp:343] Persisting action (308 bytes) to leveldb took 6.032961ms
> I0620 21:42:45.356878 20383 replica.cpp:676] Persisted action at 3
> I0620 21:42:45.360327 20381 replica.cpp:655] Replica received learned notice for position 3
> I0620 21:42:45.361325 20381 leveldb.cpp:343] Persisting action (310 bytes) to leveldb took 999225ns
> I0620 21:42:45.361372 20381 replica.cpp:676] Persisted action at 3
> I0620 21:42:45.361382 20381 replica.cpp:661] Replica learned APPEND action at position 3
> I0620 21:42:45.361780 20381 registrar.cpp:479] Successfully updated 'registry'
> I0620 21:42:45.361851 20381 log.cpp:699] Attempting to truncate the log to 3
> I0620 21:42:45.361908 20381 master.cpp:2776] Registered slave 20140620-214245-16842879-38275-20363-0 at slave(13)@127.0.1.1:38275 (saucy)
> I0620 21:42:45.361927 20381 master.cpp:3923] Adding slave 20140620-214245-16842879-38275-20363-0 at slave(13)@127.0.1.1:38275 (saucy) with cpus(*):2; mem(*):1024; disk(*):24988; ports(*):[31000-32000]
> I0620 21:42:45.362036 20381 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4
> I0620 21:42:45.362109 20381 slave.cpp:748] Registered with master master@127.0.1.1:38275; given slave ID 20140620-214245-16842879-38275-20363-0
> I0620 21:42:45.362171 20381 hierarchical_allocator_process.hpp:444] Added slave 20140620-214245-16842879-38275-20363-0 (saucy) with cpus(*):2; mem(*):1024; disk(*):24988; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):24988; ports(*):[31000-32000] available)
> I0620 21:42:45.362225 20381 hierarchical_allocator_process.hpp:750] Offering cpus(*):2; mem(*):1024; disk(*):24988; ports(*):[31000-32000] on slave 20140620-214245-16842879-38275-20363-0 to framework 20140620-214245-16842879-38275-20363-0000
> I0620 21:42:45.362303 20381 hierarchical_allocator_process.hpp:706] Performed allocation for slave 20140620-214245-16842879-38275-20363-0 in 109394ns
> I0620 21:42:45.362390 20381 master.hpp:789] Adding offer 20140620-214245-16842879-38275-20363-0 with resources cpus(*):2; mem(*):1024; disk(*):24988; ports(*):[31000-32000] on slave 20140620-214245-16842879-38275-20363-0 (saucy)
> I0620 21:42:45.362432 20381 master.cpp:3404] Sending 1 offers to framework 20140620-214245-16842879-38275-20363-0000
> I0620 21:42:45.362670 20381 sched.cpp:546] Scheduler::resourceOffers took 126669ns
> I0620 21:42:45.363452 20384 replica.cpp:508] Replica received write request for position 4
> I0620 21:42:45.364184 20387 master.hpp:799] Removing offer 20140620-214245-16842879-38275-20363-0 with resources cpus(*):2; mem(*):1024; disk(*):24988; ports(*):[31000-32000] on slave 20140620-214245-16842879-38275-20363-0 (saucy)
> I0620 21:42:45.364287 20387 master.cpp:2080] Processing reply for offers: [ 20140620-214245-16842879-38275-20363-0 ] on slave 20140620-214245-16842879-38275-20363-0 at slave(13)@127.0.1.1:38275 (saucy) for framework 20140620-214245-16842879-38275-20363-0000
> I0620 21:42:45.364327 20387 master.cpp:2166] Authorizing framework principal 'test-principal' to launch task 0 as user 'jenkins'
> I0620 21:42:45.364593 20387 master.hpp:761] Adding task 0 with resources cpus(*):1; mem(*):500 on slave 20140620-214245-16842879-38275-20363-0 (saucy)
> I0620 21:42:45.364620 20387 master.cpp:2232] Launching task 0 of framework 20140620-214245-16842879-38275-20363-0000 with resources cpus(*):1; mem(*):500 on slave 20140620-214245-16842879-38275-20363-0 at slave(13)@127.0.1.1:38275 (saucy)
> I0620 21:42:45.364735 20387 slave.cpp:983] Got assigned task 0 for framework 20140620-214245-16842879-38275-20363-0000
> I0620 21:42:45.364912 20387 slave.cpp:1093] Launching task 0 for framework 20140620-214245-16842879-38275-20363-0000
> I0620 21:42:45.366329 20384 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 2.865904ms
> I0620 21:42:45.366360 20384 replica.cpp:676] Persisted action at 4
> I0620 21:42:45.366401 20384 hierarchical_allocator_process.hpp:546] Framework 20140620-214245-16842879-38275-20363-0000 left cpus(*):1; mem(*):524; disk(*):24988; ports(*):[31000-32000] unused on slave 20140620-214245-16842879-38275-20363-0
> I0620 21:42:45.366474 20384 hierarchical_allocator_process.hpp:588] Framework 20140620-214245-16842879-38275-20363-0000 filtered slave 20140620-214245-16842879-38275-20363-0 for 5secs
> I0620 21:42:45.366657 20384 replica.cpp:655] Replica received learned notice for position 4
> I0620 21:42:45.367077 20384 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 471755ns
> I0620 21:42:45.367386 20384 leveldb.cpp:401] Deleting ~2 keys from leveldb took 41040ns
> I0620 21:42:45.367401 20384 replica.cpp:676] Persisted action at 4
> I0620 21:42:45.367413 20384 replica.cpp:661] Replica learned TRUNCATE action at position 4
> I0620 21:42:45.370185 20387 exec.cpp:131] Version: 0.20.0
> I0620 21:42:45.370872 20385 exec.cpp:181] Executor started at: executor(9)@127.0.1.1:38275 with pid 20363
> I0620 21:42:45.371237 20387 slave.cpp:1203] Queuing task '0' for executor default of framework '20140620-214245-16842879-38275-20363-0000
> I0620 21:42:45.371677 20387 slave.cpp:542] Successfully attached file '/tmp/AllocatorZooKeeperTest_0_SlaveReregistersFirst_J7cnya/slaves/20140620-214245-16842879-38275-20363-0/frameworks/20140620-214245-16842879-38275-20363-0000/executors/default/runs/4a4b2eb3-2c93-4635-8a3d-300a6f4efc86'
> I0620 21:42:45.372117 20387 slave.cpp:1714] Got registration for executor 'default' of framework 20140620-214245-16842879-38275-20363-0000
> I0620 21:42:45.372706 20386 exec.cpp:205] Executor registered on slave 20140620-214245-16842879-38275-20363-0
> I0620 21:42:45.374217 20386 exec.cpp:217] Executor::registered took 29937ns
> I0620 21:42:45.374819 20387 slave.cpp:1833] Flushing queued task 0 for executor 'default' of framework 20140620-214245-16842879-38275-20363-0000
> I0620 21:42:45.375469 20384 exec.cpp:292] Executor asked to run task '0'
> I0620 21:42:45.375632 20384 exec.cpp:301] Executor::launchTask took 37080ns
> I0620 21:42:45.376806 20384 exec.cpp:524] Executor sending status update TASK_RUNNING (UUID: 87cda68a-97bd-45e7-855b-9e1f36eb8e45) for task 0 of framework 20140620-214245-16842879-38275-20363-0000
> I0620 21:42:45.377161 20387 slave.cpp:2449] Monitoring executor 'default' of framework '20140620-214245-16842879-38275-20363-0000' in container '4a4b2eb3-2c93-4635-8a3d-300a6f4efc86'
> I0620 21:42:45.377805 20387 slave.cpp:2068] Handling status update TASK_RUNNING (UUID: 87cda68a-97bd-45e7-855b-9e1f36eb8e45) for task 0 of framework 20140620-214245-16842879-38275-20363-0000 from executor(9)@127.0.1.1:38275
> I0620 21:42:45.378384 20385 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: 87cda68a-97bd-45e7-855b-9e1f36eb8e45) for task 0 of framework 20140620-214245-16842879-38275-20363-0000
> I0620 21:42:45.378440 20385 status_update_manager.cpp:499] Creating StatusUpdate stream for task 0 of framework 20140620-214245-16842879-38275-20363-0000
> I0620 21:42:45.378518 20385 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: 87cda68a-97bd-45e7-855b-9e1f36eb8e45) for task 0 of framework 20140620-214245-16842879-38275-20363-0000 to master@127.0.1.1:38275
> I0620 21:42:45.378645 20385 master.cpp:3062] Status update TASK_RUNNING (UUID: 87cda68a-97bd-45e7-855b-9e1f36eb8e45) for task 0 of framework 20140620-214245-16842879-38275-20363-0000 from slave 20140620-214245-16842879-38275-20363-0 at slave(13)@127.0.1.1:38275 (saucy)
> I0620 21:42:45.378717 20385 sched.cpp:637] Scheduler::statusUpdate took 23671ns
> I0620 21:42:45.379030 20363 master.cpp:610] Master terminating
> I0620 21:42:45.379381 20363 master.hpp:779] Removing task 0 with resources cpus(*):1; mem(*):500 on slave 20140620-214245-16842879-38275-20363-0 (saucy)
> W0620 21:42:45.379437 20363 master.cpp:4209] Removing task 0 of framework 20140620-214245-16842879-38275-20363-0000 and slave 20140620-214245-16842879-38275-20363-0 in non-terminal state TASK_RUNNING
> 2014-06-20 21:42:45,381:20363(0x2b84755219c0):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x146bcbbc114000a to [127.0.0.1:40498]
> 2014-06-20 21:42:45,382:20363(0x2b84755219c0):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x146bcbbc114000d to [127.0.0.1:40498]
> I0620 21:42:45.385253 20363 contender.cpp:186] Now cancelling the membership: 3
> 2014-06-20 21:42:45,386:20363(0x2b84755219c0):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x146bcbbc114000b to [127.0.0.1:40498]
> 2014-06-20 21:42:45,389:20363(0x2b84755219c0):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x146bcbbc114000c to [127.0.0.1:40498]
> I0620 21:42:45.391755 20381 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
> I0620 21:42:45.391811 20381 detector.cpp:126] The current leader (id=3) is lost
> I0620 21:42:45.391820 20381 detector.cpp:138] Detected a new leader: None
> I0620 21:42:45.393132 20383 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
> I0620 21:42:45.393180 20383 detector.cpp:126] The current leader (id=3) is lost
> I0620 21:42:45.393189 20383 detector.cpp:138] Detected a new leader: None
> I0620 21:42:45.393275 20383 sched.cpp:229] Scheduler::disconnected took 14074ns
> I0620 21:42:45.393286 20383 sched.cpp:251] No master detected
> I0620 21:42:45.394939 20387 slave.cpp:2311] master@127.0.1.1:38275 exited
> W0620 21:42:45.395740 20387 slave.cpp:2314] Master disconnected! Waiting for a new master to be elected
> I0620 21:42:45.396463 20387 slave.cpp:626] Lost leading master
> I0620 21:42:45.396770 20387 slave.cpp:630] Detecting new master
> I0620 21:42:45.397200 20387 slave.cpp:2226] Status update manager successfully handled status update TASK_RUNNING (UUID: 87cda68a-97bd-45e7-855b-9e1f36eb8e45) for task 0 of framework 20140620-214245-16842879-38275-20363-0000
> I0620 21:42:45.397739 20387 slave.cpp:2232] Sending acknowledgement for status update TASK_RUNNING (UUID: 87cda68a-97bd-45e7-855b-9e1f36eb8e45) for task 0 of framework 20140620-214245-16842879-38275-20363-0000 to executor(9)@127.0.1.1:38275
> I0620 21:42:45.398138 20385 exec.cpp:338] Executor received status update acknowledgement 87cda68a-97bd-45e7-855b-9e1f36eb8e45 for task 0 of framework 20140620-214245-16842879-38275-20363-0000
> I0620 21:42:45.399045 20363 leveldb.cpp:176] Opened db in 6.831599ms
> I0620 21:42:45.401203 20363 leveldb.cpp:183] Compacted db in 1.865654ms
> I0620 21:42:45.401631 20363 leveldb.cpp:198] Created db iterator in 33550ns
> I0620 21:42:45.401917 20363 leveldb.cpp:204] Seeked to beginning of db in 36970ns
> I0620 21:42:45.402220 20363 leveldb.cpp:273] Iterated through 3 keys in the db in 55304ns
> I0620 21:42:45.402501 20363 replica.cpp:741] Replica recovered with log positions 3 -> 4 with 0 holes and 0 unlearned
> 2014-06-20 21:42:45,402:20363(0x2b847d3e0700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
> 2014-06-20 21:42:45,402:20363(0x2b847d3e0700):ZOO_INFO@log_env@716: Client environment:host.name=saucy
> 2014-06-20 21:42:45,402:20363(0x2b847d3e0700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
> 2014-06-20 21:42:45,402:20363(0x2b847d3e0700):ZOO_INFO@log_env@724: Client environment:os.arch=3.11.0-23-generic
> 2014-06-20 21:42:45,402:20363(0x2b847d3e0700):ZOO_INFO@log_env@725: Client environment:os.version=#40-Ubuntu SMP Wed Jun 4 21:05:23 UTC 2014
> 2014-06-20 21:42:45,403:20363(0x2b847d3e0700):ZOO_INFO@log_env@733: Client environment:user.name=jenkins
> 2014-06-20 21:42:45,403:20363(0x2b847d3e0700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
> 2014-06-20 21:42:45,403:20363(0x2b847d3e0700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/AllocatorZooKeeperTest_0_SlaveReregistersFirst_aWAV8S
> 2014-06-20 21:42:45,403:20363(0x2b847d3e0700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:40498 sessionTimeout=10000 watcher=0x2b8476040110 sessionId=0 sessionPasswd=<null> context=0x2b84900103d0 flags=0
> 2014-06-20 21:42:45,403:20363(0x2b847cfde700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
> 2014-06-20 21:42:45,403:20363(0x2b847cfde700):ZOO_INFO@log_env@716: Client environment:host.name=saucy
> 2014-06-20 21:42:45,403:20363(0x2b847cfde700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
> 2014-06-20 21:42:45,403:20363(0x2b847cfde700):ZOO_INFO@log_env@724: Client environment:os.arch=3.11.0-23-generic
> 2014-06-20 21:42:45,403:20363(0x2b847cfde700):ZOO_INFO@log_env@725: Client environment:os.version=#40-Ubuntu SMP Wed Jun 4 21:05:23 UTC 2014
> 2014-06-20 21:42:45,403:20363(0x2b847cfde700):ZOO_INFO@log_env@733: Client environment:user.name=jenkins
> 2014-06-20 21:42:45,403:20363(0x2b847cfde700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
> 2014-06-20 21:42:45,403:20363(0x2b847cfde700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/AllocatorZooKeeperTest_0_SlaveReregistersFirst_aWAV8S
> 2014-06-20 21:42:45,403:20363(0x2b847cfde700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:40498 sessionTimeout=10000 watcher=0x2b8476040110 sessionId=0 sessionPasswd=<null> context=0x2b8494005ab0 flags=0
> I0620 21:42:45.404222 20385 log.cpp:238] Attempting to join replica to ZooKeeper group
> I0620 21:42:45.404366 20385 recover.cpp:425] Starting replica recovery
> I0620 21:42:45.404435 20385 recover.cpp:451] Replica is in VOTING status
> I0620 21:42:45.404470 20385 recover.cpp:440] Recover process terminated
> 2014-06-20 21:42:45,405:20363(0x2b847dde5700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
> 2014-06-20 21:42:45,405:20363(0x2b847dde5700):ZOO_INFO@log_env@716: Client environment:host.name=saucy
> 2014-06-20 21:42:45,405:20363(0x2b847dde5700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
> 2014-06-20 21:42:45,405:20363(0x2b847dde5700):ZOO_INFO@log_env@724: Client environment:os.arch=3.11.0-23-generic
> 2014-06-20 21:42:45,405:20363(0x2b847dde5700):ZOO_INFO@log_env@725: Client environment:os.version=#40-Ubuntu SMP Wed Jun 4 21:05:23 UTC 2014
> 2014-06-20 21:42:45,405:20363(0x2b847dde5700):ZOO_INFO@log_env@733: Client environment:user.name=jenkins
> 2014-06-20 21:42:45,405:20363(0x2b847dde5700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
> 2014-06-20 21:42:45,405:20363(0x2b847dde5700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/AllocatorZooKeeperTest_0_SlaveReregistersFirst_aWAV8S
> 2014-06-20 21:42:45,405:20363(0x2b847dde5700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:40498 sessionTimeout=10000 watcher=0x2b8476040110 sessionId=0 sessionPasswd=<null> context=0x2b84881240a0 flags=0
> 2014-06-20 21:42:45,405:20363(0x2b847d7e2700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
> 2014-06-20 21:42:45,405:20363(0x2b847d7e2700):ZOO_INFO@log_env@716: Client environment:host.name=saucy
> 2014-06-20 21:42:45,406:20363(0x2b847d7e2700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
> 2014-06-20 21:42:45,406:20363(0x2b847d7e2700):ZOO_INFO@log_env@724: Client environment:os.arch=3.11.0-23-generic
> 2014-06-20 21:42:45,406:20363(0x2b847d7e2700):ZOO_INFO@log_env@725: Client environment:os.version=#40-Ubuntu SMP Wed Jun 4 21:05:23 UTC 2014
> 2014-06-20 21:42:45,406:20363(0x2b847d7e2700):ZOO_INFO@log_env@733: Client environment:user.name=jenkins
> 2014-06-20 21:42:45,406:20363(0x2b847d7e2700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
> 2014-06-20 21:42:45,406:20363(0x2b847d7e2700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/AllocatorZooKeeperTest_0_SlaveReregistersFirst_aWAV8S
> 2014-06-20 21:42:45,406:20363(0x2b847d7e2700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:40498 sessionTimeout=10000 watcher=0x2b8476040110 sessionId=0 sessionPasswd=<null> context=0x2b848c011680 flags=0
> 2014-06-20 21:42:45,414:20363(0x2b84a7746700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:40498]
> 2014-06-20 21:42:45,417:20363(0x2b84a7746700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:40498], sessionId=0x146bcbbc1140010, negotiated timeout=10000
> I0620 21:42:45.419651 20386 group.cpp:313] Group process (group(18)@127.0.1.1:38275) connected to ZooKeeper
> I0620 21:42:45.419726 20386 group.cpp:787] Syncing group operations: queue size (joins, cancels, datas) = (1, 0, 0)
> I0620 21:42:45.419739 20386 group.cpp:385] Trying to create path '/znode/log_replicas' in ZooKeeper
> 2014-06-20 21:42:45,420:20363(0x2b84a815b700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:40498]
> 2014-06-20 21:42:45,423:20363(0x2b84a855d700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:40498]
> 2014-06-20 21:42:45,423:20363(0x2b84a7344700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:40498]
> 2014-06-20 21:42:45,425:20363(0x2b84a855d700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:40498], sessionId=0x146bcbbc1140012, negotiated timeout=10000
> I0620 21:42:45.426098 20385 group.cpp:313] Group process (group(19)@127.0.1.1:38275) connected to ZooKeeper
> I0620 21:42:45.426120 20385 group.cpp:787] Syncing group operations: queue size (joins, cancels, datas) = (0, 0, 0)
> I0620 21:42:45.426126 20385 group.cpp:385] Trying to create path '/znode' in ZooKeeper
> 2014-06-20 21:42:45,426:20363(0x2b84a815b700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:40498], sessionId=0x146bcbbc1140011, negotiated timeout=10000
> I0620 21:42:45.426863 20383 group.cpp:313] Group process (group(20)@127.0.1.1:38275) connected to ZooKeeper
> I0620 21:42:45.426884 20383 group.cpp:787] Syncing group operations: queue size (joins, cancels, datas) = (0, 0, 0)
> I0620 21:42:45.426892 20383 group.cpp:385] Trying to create path '/znode' in ZooKeeper
> I0620 21:42:45.427383 20388 master.cpp:286] Master 20140620-214245-16842879-38275-20363 (saucy) started on 127.0.1.1:38275
> I0620 21:42:45.427417 20388 master.cpp:323] Master only allowing authenticated frameworks to register
> I0620 21:42:45.427423 20388 master.cpp:328] Master only allowing authenticated slaves to register
> I0620 21:42:45.427429 20388 credentials.hpp:35] Loading credentials for authentication from '/tmp/AllocatorZooKeeperTest_0_SlaveReregistersFirst_aWAV8S/credentials'
> I0620 21:42:45.427554 20388 master.cpp:354] Authorization enabled
> I0620 21:42:45.427976 20388 master.cpp:120] No whitelist given. Advertising offers for all slaves
> I0620 21:42:45.428237 20388 hierarchical_allocator_process.hpp:301] Initializing hierarchical allocator process with master : master@127.0.1.1:38275
> I0620 21:42:45.428282 20388 contender.cpp:131] Joining the ZK group
> 2014-06-20 21:42:45,433:20363(0x2b84a7344700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:40498], sessionId=0x146bcbbc1140013, negotiated timeout=10000
> I0620 21:42:45.434380 20381 group.cpp:313] Group process (group(17)@127.0.1.1:38275) connected to ZooKeeper
> I0620 21:42:45.434401 20381 group.cpp:787] Syncing group operations: queue size (joins, cancels, datas) = (0, 0, 0)
> I0620 21:42:45.434408 20381 group.cpp:385] Trying to create path '/znode/log_replicas' in ZooKeeper
> I0620 21:42:45.443786 20383 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
> I0620 21:42:45.445565 20385 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
> I0620 21:42:45.446782 20381 network.hpp:423] ZooKeeper group memberships changed
> I0620 21:42:45.446884 20381 group.cpp:658] Trying to get '/znode/log_replicas/0000000003' in ZooKeeper
> I0620 21:42:45.450687 20387 contender.cpp:247] New candidate (id='4') has entered the contest for leadership
> I0620 21:42:45.451870 20381 network.hpp:461] ZooKeeper group PIDs: { log-replica(14)@127.0.1.1:38275 }
> I0620 21:42:45.452761 20386 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
> I0620 21:42:45.452821 20386 detector.cpp:138] Detected a new leader: (id='4')
> I0620 21:42:45.452930 20386 group.cpp:658] Trying to get '/znode/info_0000000004' in ZooKeeper
> I0620 21:42:45.454017 20388 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
> I0620 21:42:45.454072 20388 detector.cpp:138] Detected a new leader: (id='4')
> I0620 21:42:45.454164 20388 group.cpp:658] Trying to get '/znode/info_0000000004' in ZooKeeper
> I0620 21:42:45.455328 20384 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
> I0620 21:42:45.455384 20384 detector.cpp:138] Detected a new leader: (id='4')
> I0620 21:42:45.455471 20384 group.cpp:658] Trying to get '/znode/info_0000000004' in ZooKeeper
> I0620 21:42:45.461225 20385 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
> I0620 21:42:45.462023 20386 detector.cpp:382] A new leading master (UPID=master@127.0.1.1:38275) is detected
> I0620 21:42:45.462116 20386 sched.cpp:235] New master detected at master@127.0.1.1:38275
> I0620 21:42:45.462133 20386 sched.cpp:285] Authenticating with master master@127.0.1.1:38275
> I0620 21:42:45.462224 20386 authenticatee.hpp:128] Creating new client SASL connection
> I0620 21:42:45.462666 20386 master.cpp:803] Dropping 'mesos.internal.AuthenticateMessage' message since not elected yet
> I0620 21:42:45.463469 20388 detector.cpp:382] A new leading master (UPID=master@127.0.1.1:38275) is detected
> I0620 21:42:45.463551 20388 slave.cpp:581] New master detected at master@127.0.1.1:38275
> I0620 21:42:45.463575 20388 slave.cpp:657] Authenticating with master master@127.0.1.1:38275
> I0620 21:42:45.463614 20388 slave.cpp:630] Detecting new master
> I0620 21:42:45.463652 20388 status_update_manager.cpp:167] New master detected at master@127.0.1.1:38275
> W0620 21:42:45.463666 20388 status_update_manager.cpp:181] Resending status update TASK_RUNNING (UUID: 87cda68a-97bd-45e7-855b-9e1f36eb8e45) for task 0 of framework 20140620-214245-16842879-38275-20363-0000
> I0620 21:42:45.463678 20388 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: 87cda68a-97bd-45e7-855b-9e1f36eb8e45) for task 0 of framework 20140620-214245-16842879-38275-20363-0000 to master@127.0.1.1:38275
> I0620 21:42:45.463737 20388 authenticatee.hpp:128] Creating new client SASL connection
> I0620 21:42:45.464016 20381 master.cpp:803] Dropping 'mesos.internal.StatusUpdateMessage' message since not elected yet
> I0620 21:42:45.464373 20388 master.cpp:803] Dropping 'mesos.internal.AuthenticateMessage' message since not elected yet
> I0620 21:42:45.465137 20384 detector.cpp:382] A new leading master (UPID=master@127.0.1.1:38275) is detected
> I0620 21:42:45.465214 20384 master.cpp:1077] The newly elected leader is master@127.0.1.1:38275 with id 20140620-214245-16842879-38275-20363
> I0620 21:42:45.465229 20384 master.cpp:1090] Elected as the leading master!
> I0620 21:42:45.465234 20384 master.cpp:908] Recovering from registrar
> I0620 21:42:45.465293 20384 registrar.cpp:313] Recovering registrar
> I0620 21:42:45.465517 20384 log.cpp:656] Attempting to start the writer
> I0620 21:42:45.465809 20384 replica.cpp:474] Replica received implicit promise request with proposal 2
> I0620 21:42:45.466706 20384 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 890322ns
> I0620 21:42:45.466943 20384 replica.cpp:342] Persisted promised to 2
> I0620 21:42:45.467133 20384 coordinator.cpp:230] Coordinator attemping to fill missing position
> I0620 21:42:45.467206 20384 log.cpp:672] Writer started with ending position 4
> I0620 21:42:45.467443 20384 leveldb.cpp:438] Reading position from leveldb took 37530ns
> I0620 21:42:45.467474 20384 leveldb.cpp:438] Reading position from leveldb took 14391ns
> I0620 21:42:45.467728 20384 registrar.cpp:346] Successfully fetched the registry (250B)
> I0620 21:42:45.467758 20384 registrar.cpp:422] Attempting to update the 'registry'
> I0620 21:42:45.469328 20383 log.cpp:680] Attempting to append 289 bytes to the log
> I0620 21:42:45.469377 20383 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 5
> I0620 21:42:45.469573 20383 replica.cpp:508] Replica received write request for position 5
> I0620 21:42:45.470195 20383 leveldb.cpp:343] Persisting action (308 bytes) to leveldb took 616575ns
> I0620 21:42:45.470222 20383 replica.cpp:676] Persisted action at 5
> I0620 21:42:45.470396 20383 replica.cpp:655] Replica received learned notice for position 5
> I0620 21:42:45.470780 20383 leveldb.cpp:343] Persisting action (310 bytes) to leveldb took 379875ns
> I0620 21:42:45.470800 20383 replica.cpp:676] Persisted action at 5
> I0620 21:42:45.470808 20383 replica.cpp:661] Replica learned APPEND action at position 5
> I0620 21:42:45.471047 20383 log.cpp:699] Attempting to truncate the log to 5
> I0620 21:42:45.471086 20383 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 6
> I0620 21:42:45.471261 20383 replica.cpp:508] Replica received write request for position 6
> I0620 21:42:45.474760 20383 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 3.492671ms
> I0620 21:42:45.475158 20383 replica.cpp:676] Persisted action at 6
> I0620 21:42:45.478940 20381 replica.cpp:655] Replica received learned notice for position 6
> I0620 21:42:45.479497 20381 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 546053ns
> I0620 21:42:45.479533 20381 leveldb.cpp:401] Deleting ~2 keys from leveldb took 24872ns
> I0620 21:42:45.479544 20381 replica.cpp:676] Persisted action at 6
> I0620 21:42:45.479552 20381 replica.cpp:661] Replica learned TRUNCATE action at position 6
> I0620 21:42:45.479893 20384 registrar.cpp:479] Successfully updated 'registry'
> I0620 21:42:45.480226 20384 registrar.cpp:372] Successfully recovered registrar
> I0620 21:42:45.480629 20385 master.cpp:935] Recovered 1 slaves from the Registry (250B) ; allowing 10mins for slaves to re-register
> I0620 21:42:46.428702 20387 hierarchical_allocator_process.hpp:724] No resources available to allocate!
> I0620 21:42:46.428740 20387 hierarchical_allocator_process.hpp:686] Performed allocation for 0 slaves in 57551ns
> I0620 21:42:47.429708 20387 hierarchical_allocator_process.hpp:724] No resources available to allocate!
> I0620 21:42:47.429745 20387 hierarchical_allocator_process.hpp:686] Performed allocation for 0 slaves in 52238ns
> I0620 21:42:48.430711 20387 hierarchical_allocator_process.hpp:724] No resources available to allocate!
> I0620 21:42:48.430822 20387 hierarchical_allocator_process.hpp:686] Performed allocation for 0 slaves in 128411ns
> I0620 21:42:49.431538 20382 hierarchical_allocator_process.hpp:724] No resources available to allocate!
> I0620 21:42:49.431576 20382 hierarchical_allocator_process.hpp:686] Performed allocation for 0 slaves in 55263ns
> I0620 21:42:50.428278 20387 master.cpp:120] No whitelist given. Advertising offers for all slaves
> I0620 21:42:50.431800 20385 hierarchical_allocator_process.hpp:724] No resources available to allocate!
> I0620 21:42:50.431818 20385 hierarchical_allocator_process.hpp:686] Performed allocation for 0 slaves in 29293ns
> W0620 21:42:50.463484 20383 sched.cpp:380] Authentication timed out
> I0620 21:42:50.463587 20383 sched.cpp:340] Failed to authenticate with master master@127.0.1.1:38275: Authentication discarded
> I0620 21:42:50.463618 20383 sched.cpp:285] Authenticating with master master@127.0.1.1:38275
> I0620 21:42:50.463687 20383 authenticatee.hpp:128] Creating new client SASL connection
> I0620 21:42:50.464334 20383 master.cpp:3457] Authenticating scheduler-b20a9ea5-51ce-43ec-b8b9-e9c0e95af495@127.0.1.1:38275
> I0620 21:42:50.464468 20383 authenticator.hpp:156] Creating new server SASL connection
> I0620 21:42:50.464579 20383 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
> I0620 21:42:50.464599 20383 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0620 21:42:50.464622 20383 authenticator.hpp:262] Received SASL authentication start
> I0620 21:42:50.464673 20383 authenticator.hpp:384] Authentication requires more steps
> I0620 21:42:50.464699 20383 authenticatee.hpp:265] Received SASL authentication step
> I0620 21:42:50.464730 20383 authenticator.hpp:290] Received SASL authentication step
> I0620 21:42:50.464746 20383 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'saucy' server FQDN: 'saucy' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0620 21:42:50.464753 20383 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
> I0620 21:42:50.464766 20383 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0620 21:42:50.464774 20383 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'saucy' server FQDN: 'saucy' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0620 21:42:50.464781 20383 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0620 21:42:50.464786 20383 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0620 21:42:50.464795 20383 authenticator.hpp:376] Authentication success
> I0620 21:42:50.464820 20383 authenticatee.hpp:305] Authentication success
> I0620 21:42:50.464840 20383 master.cpp:3497] Successfully authenticated principal 'test-principal' at scheduler-b20a9ea5-51ce-43ec-b8b9-e9c0e95af495@127.0.1.1:38275
> I0620 21:42:50.464905 20383 sched.cpp:359] Successfully authenticated with master master@127.0.1.1:38275
> I0620 21:42:50.464917 20383 sched.cpp:478] Sending registration request to master@127.0.1.1:38275
> W0620 21:42:50.466374 20384 slave.cpp:731] Authentication timed out
> W0620 21:42:50.466439 20384 slave.cpp:695] Failed to authenticate with master master@127.0.1.1:38275: Authentication discarded
> I0620 21:42:50.466464 20384 slave.cpp:657] Authenticating with master master@127.0.1.1:38275
> I0620 21:42:50.466513 20384 authenticatee.hpp:128] Creating new client SASL connection
> I0620 21:42:50.466624 20384 master.cpp:3457] Authenticating slave(13)@127.0.1.1:38275
> I0620 21:42:50.466696 20384 authenticator.hpp:156] Creating new server SASL connection
> I0620 21:42:50.467147 20384 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
> I0620 21:42:50.467172 20384 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0620 21:42:50.467201 20384 authenticator.hpp:262] Received SASL authentication start
> I0620 21:42:50.467237 20384 authenticator.hpp:384] Authentication requires more steps
> I0620 21:42:50.467262 20384 authenticatee.hpp:265] Received SASL authentication step
> I0620 21:42:50.467289 20384 authenticator.hpp:290] Received SASL authentication step
> I0620 21:42:50.467303 20384 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'saucy' server FQDN: 'saucy' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0620 21:42:50.467309 20384 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
> I0620 21:42:50.467317 20384 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0620 21:42:50.467325 20384 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'saucy' server FQDN: 'saucy' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0620 21:42:50.467331 20384 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0620 21:42:50.467335 20384 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0620 21:42:50.467345 20384 authenticator.hpp:376] Authentication success
> I0620 21:42:50.467366 20384 authenticatee.hpp:305] Authentication success
> I0620 21:42:50.467385 20384 master.cpp:3497] Successfully authenticated principal 'test-principal' at slave(13)@127.0.1.1:38275
> I0620 21:42:50.467443 20384 slave.cpp:714] Successfully authenticated with master master@127.0.1.1:38275
> I0620 21:42:50.467525 20384 slave.cpp:952] Will retry registration in 18.988786ms if necessary
> I0620 21:42:50.467613 20384 master.cpp:2911] Re-registering slave 20140620-214245-16842879-38275-20363-0 at slave(13)@127.0.1.1:38275 (saucy)
> I0620 21:42:50.467736 20384 registrar.cpp:422] Attempting to update the 'registry'
> I0620 21:42:50.469023 20384 log.cpp:680] Attempting to append 289 bytes to the log
> I0620 21:42:50.469075 20384 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 7
> I0620 21:42:50.469287 20384 replica.cpp:508] Replica received write request for position 7
> I0620 21:42:50.469833 20384 leveldb.cpp:343] Persisting action (308 bytes) to leveldb took 538486ns
> I0620 21:42:50.470057 20384 replica.cpp:676] Persisted action at 7
> I0620 21:42:50.474959 20387 replica.cpp:655] Replica received learned notice for position 7
> I0620 21:42:50.475807 20387 leveldb.cpp:343] Persisting action (310 bytes) to leveldb took 836877ns
> I0620 21:42:50.475829 20387 replica.cpp:676] Persisted action at 7
> I0620 21:42:50.475837 20387 replica.cpp:661] Replica learned APPEND action at position 7
> I0620 21:42:50.476138 20387 registrar.cpp:479] Successfully updated 'registry'
> I0620 21:42:50.476235 20387 log.cpp:699] Attempting to truncate the log to 7
> I0620 21:42:50.476291 20387 master.cpp:2962] Re-registered slave 20140620-214245-16842879-38275-20363-0 at slave(13)@127.0.1.1:38275 (saucy)
> I0620 21:42:50.476305 20387 master.cpp:3923] Adding slave 20140620-214245-16842879-38275-20363-0 at slave(13)@127.0.1.1:38275 (saucy) with cpus(*):2; mem(*):1024; disk(*):24988; ports(*):[31000-32000]
> I0620 21:42:50.476390 20387 master.hpp:761] Adding task 0 with resources cpus(*):1; mem(*):500 on slave 20140620-214245-16842879-38275-20363-0 (saucy)
> W0620 21:42:50.476414 20387 master.cpp:4014] Possibly orphaned task 0 of framework 20140620-214245-16842879-38275-20363-0000 running on slave 20140620-214245-16842879-38275-20363-0 at slave(13)@127.0.1.1:38275 (saucy)
> I0620 21:42:50.476479 20387 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 8
> I0620 21:42:50.476541 20387 slave.cpp:798] Re-registered with master master@127.0.1.1:38275
> I0620 21:42:50.476688 20387 hierarchical_allocator_process.hpp:444] Added slave 20140620-214245-16842879-38275-20363-0 (saucy) with cpus(*):2; mem(*):1024; disk(*):24988; ports(*):[31000-32000] (and cpus(*):1; mem(*):524; disk(*):24988; ports(*):[31000-32000] available)
> I0620 21:42:50.476729 20387 hierarchical_allocator_process.hpp:706] Performed allocation for slave 20140620-214245-16842879-38275-20363-0 in 16253ns
> I0620 21:42:50.477288 20386 replica.cpp:508] Replica received write request for position 8
> I0620 21:42:50.477546 20386 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 249243ns
> I0620 21:42:50.477566 20386 replica.cpp:676] Persisted action at 8
> I0620 21:42:50.477874 20386 replica.cpp:655] Replica received learned notice for position 8
> I0620 21:42:50.478205 20386 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 322409ns
> I0620 21:42:50.478241 20386 leveldb.cpp:401] Deleting ~2 keys from leveldb took 24230ns
> I0620 21:42:50.478252 20386 replica.cpp:676] Persisted action at 8
> I0620 21:42:50.478260 20386 replica.cpp:661] Replica learned TRUNCATE action at position 8
> I0620 21:42:51.432675 20381 hierarchical_allocator_process.hpp:686] Performed allocation for 1 slaves in 75417ns
> I0620 21:42:51.466063 20381 sched.cpp:478] Sending registration request to master@127.0.1.1:38275
> I0620 21:42:51.466166 20381 master.cpp:1304] Received re-registration request from framework 20140620-214245-16842879-38275-20363-0000 at scheduler-b20a9ea5-51ce-43ec-b8b9-e9c0e95af495@127.0.1.1:38275
> I0620 21:42:51.466181 20381 master.cpp:1156] Authorizing framework principal 'test-principal' to receive offers for role '*'
> I0620 21:42:51.466280 20381 master.cpp:1355] Re-registering framework 20140620-214245-16842879-38275-20363-0000 at scheduler-b20a9ea5-51ce-43ec-b8b9-e9c0e95af495@127.0.1.1:38275
> I0620 21:42:51.466473 20381 sched.cpp:409] Framework registered with 20140620-214245-16842879-38275-20363-0000
> I0620 21:42:51.466505 20381 sched.cpp:423] Scheduler::registered took 19872ns
> I0620 21:42:51.466578 20381 slave.cpp:1564] Updating framework 20140620-214245-16842879-38275-20363-0000 pid to scheduler-b20a9ea5-51ce-43ec-b8b9-e9c0e95af495@127.0.1.1:38275
> I0620 21:42:51.466661 20381 hierarchical_allocator_process.hpp:331] Added framework 20140620-214245-16842879-38275-20363-0000
> I0620 21:42:51.466701 20381 hierarchical_allocator_process.hpp:750] Offering cpus(*):1; mem(*):524; disk(*):24988; ports(*):[31000-32000] on slave 20140620-214245-16842879-38275-20363-0 to framework 20140620-214245-16842879-38275-20363-0000
> I0620 21:42:51.466836 20381 hierarchical_allocator_process.hpp:686] Performed allocation for 1 slaves in 171501ns
> W0620 21:42:51.466856 20381 status_update_manager.cpp:181] Resending status update TASK_RUNNING (UUID: 87cda68a-97bd-45e7-855b-9e1f36eb8e45) for task 0 of framework 20140620-214245-16842879-38275-20363-0000
> I0620 21:42:51.466868 20381 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: 87cda68a-97bd-45e7-855b-9e1f36eb8e45) for task 0 of framework 20140620-214245-16842879-38275-20363-0000 to master@127.0.1.1:38275
> I0620 21:42:51.466946 20381 master.hpp:789] Adding offer 20140620-214245-16842879-38275-20363-0 with resources cpus(*):1; mem(*):524; disk(*):24988; ports(*):[31000-32000] on slave 20140620-214245-16842879-38275-20363-0 (saucy)
> I0620 21:42:51.466986 20381 master.cpp:3404] Sending 1 offers to framework 20140620-214245-16842879-38275-20363-0000
> I0620 21:42:51.467066 20381 master.cpp:3062] Status update TASK_RUNNING (UUID: 87cda68a-97bd-45e7-855b-9e1f36eb8e45) for task 0 of framework 20140620-214245-16842879-38275-20363-0000 from slave 20140620-214245-16842879-38275-20363-0 at slave(13)@127.0.1.1:38275 (saucy)
> I0620 21:42:51.467201 20381 sched.cpp:546] Scheduler::resourceOffers took 29042ns
> tests/allocator_zookeeper_tests.cpp:220: Failure
> Mock function called more times than expected - returning directly.
> Function call: statusUpdate(0x7fff02ad01e0, @0x2b8494012130 80-byte object <60-CE A1-76 84-2B 00-00 00-00 00-00 00-00 00-00 E0-80 00-94 84-2B 00-00 48-B0 20-01 00-00 00-00 48-B0 20-01 00-00 00-00 E0-CF 01-94 84-2B 00-00 01-00 00-00 00-43 75-72 00-00 00-00 00-00 00-00 DD-0A D8-52 43-E9 D4-41 00-00 00-00 53-00 00-00>)
> Expected: to be called once
> Actual: called twice - over-saturated and active
> I0620 21:42:51.467337 20381 sched.cpp:637] Scheduler::statusUpdate took 101482ns
> I0620 21:42:51.467392 20381 master.cpp:2586] Forwarding status update acknowledgement 87cda68a-97bd-45e7-855b-9e1f36eb8e45 for task 0 of framework 20140620-214245-16842879-38275-20363-0000 to slave 20140620-214245-16842879-38275-20363-0 at slave(13)@127.0.1.1:38275 (saucy)
> I0620 21:42:51.467782 20383 status_update_manager.cpp:398] Received status update acknowledgement (UUID: 87cda68a-97bd-45e7-855b-9e1f36eb8e45) for task 0 of framework 20140620-214245-16842879-38275-20363-0000
> I0620 21:42:51.467869 20383 slave.cpp:1654] Status update manager successfully handled status update acknowledgement (UUID: 87cda68a-97bd-45e7-855b-9e1f36eb8e45) for task 0 of framework 20140620-214245-16842879-38275-20363-0000
> I0620 21:42:51.468070 20363 master.cpp:610] Master terminating
> I0620 21:42:51.468116 20363 master.hpp:779] Removing task 0 with resources cpus(*):1; mem(*):500 on slave 20140620-214245-16842879-38275-20363-0 (saucy)
> W0620 21:42:51.468149 20363 master.cpp:4209] Removing task 0 of framework 20140620-214245-16842879-38275-20363-0000 and slave 20140620-214245-16842879-38275-20363-0 in non-terminal state TASK_RUNNING
> I0620 21:42:51.468179 20363 master.hpp:799] Removing offer 20140620-214245-16842879-38275-20363-0 with resources cpus(*):1; mem(*):524; disk(*):24988; ports(*):[31000-32000] on slave 20140620-214245-16842879-38275-20363-0 (saucy)
> I0620 21:42:51.468865 20383 sched.cpp:747] Stopping framework '20140620-214245-16842879-38275-20363-0000'
> I0620 21:42:51.468901 20383 slave.cpp:2311] master@127.0.1.1:38275 exited
> W0620 21:42:51.468912 20383 slave.cpp:2314] Master disconnected! Waiting for a new master to be elected
> 2014-06-20 21:42:51,469:20363(0x2b84755219c0):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x146bcbbc1140010 to [127.0.0.1:40498]
> 2014-06-20 21:42:51,470:20363(0x2b84755219c0):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x146bcbbc1140013 to [127.0.0.1:40498]
> I0620 21:42:51.470531 20363 contender.cpp:186] Now cancelling the membership: 4
> 2014-06-20 21:42:51,472:20363(0x2b84755219c0):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x146bcbbc1140012 to [127.0.0.1:40498]
> I0620 21:42:51.478623 20383 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
> 2014-06-20 21:42:51,479:20363(0x2b84755219c0):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x146bcbbc1140011 to [127.0.0.1:40498]
> I0620 21:42:51.479737 20363 slave.cpp:466] Slave terminating
> I0620 21:42:51.479759 20363 slave.cpp:1387] Asked to shut down framework 20140620-214245-16842879-38275-20363-0000 by @0.0.0.0:0
> I0620 21:42:51.479770 20363 slave.cpp:1412] Shutting down framework 20140620-214245-16842879-38275-20363-0000
> I0620 21:42:51.479781 20363 slave.cpp:2792] Shutting down executor 'default' of framework 20140620-214245-16842879-38275-20363-0000
> I0620 21:42:51.491413 20386 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
> I0620 21:42:51.491477 20386 detector.cpp:126] The current leader (id=4) is lost
> I0620 21:42:51.491485 20386 detector.cpp:138] Detected a new leader: None
> I0620 21:42:51.491637 20385 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
> I0620 21:42:51.491672 20385 detector.cpp:126] The current leader (id=4) is lost
> I0620 21:42:51.491679 20385 detector.cpp:138] Detected a new leader: None
> 2014-06-20 21:42:51,494:20363(0x2b84755219c0):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x146bcbbc114000e to [127.0.0.1:40498]
> 2014-06-20 21:42:51,497:20363(0x2b84755219c0):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x146bcbbc114000f to [127.0.0.1:40498]
> [ FAILED ] AllocatorZooKeeperTest/0.SlaveReregistersFirst, where TypeParam = mesos::internal::master::allocator::HierarchicalAllocatorProcess<mesos::internal::master::allocator::DRFSorter, mesos::internal::master::allocator::DRFSorter> (6275 ms)
> I0620 21:42:51.502812 20363 jvm.cpp:567] Looking up method shutdown()V
> I0620 21:42:51.505517 20363 zookeeper_test_server.cpp:122] Shutdown ZooKeeperTestServer on port 40498
> {noformat}
> {noformat:title=full log AllocatorZooKeeperTest/0.FrameworkReregistersFirst}
> [ RUN ] AllocatorZooKeeperTest/0.FrameworkReregistersFirst
> Using temporary directory '/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_Cr5GZg'
> I0620 22:12:29.007104 15771 leveldb.cpp:176] Opened db in 28.48695ms
> I0620 22:12:29.016083 15771 leveldb.cpp:183] Compacted db in 8.803847ms
> I0620 22:12:29.016229 15771 leveldb.cpp:198] Created db iterator in 5304ns
> I0620 22:12:29.016473 15771 leveldb.cpp:204] Seeked to beginning of db in 1280ns
> I0620 22:12:29.016600 15771 leveldb.cpp:273] Iterated through 0 keys in the db in 578ns
> I0620 22:12:29.016762 15771 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
> 2014-06-20 22:12:29,017:15771(0x2b2846e4a700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
> 2014-06-20 22:12:29,017:15771(0x2b2846e4a700):ZOO_INFO@log_env@716: Client environment:host.name=precise
> 2014-06-20 22:12:29,017:15771(0x2b2846e4a700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
> 2014-06-20 22:12:29,017:15771(0x2b2846e4a700):ZOO_INFO@log_env@724: Client environment:os.arch=3.2.0-64-generic
> 2014-06-20 22:12:29,017:15771(0x2b2846e4a700):ZOO_INFO@log_env@725: Client environment:os.version=#97-Ubuntu SMP Wed Jun 4 22:04:21 UTC 2014
> 2014-06-20 22:12:29,017:15771(0x2b2846e4a700):ZOO_INFO@log_env@733: Client environment:user.name=(null)
> 2014-06-20 22:12:29,017:15771(0x2b2846e4a700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
> 2014-06-20 22:12:29,017:15771(0x2b2846e4a700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_Cr5GZg
> 2014-06-20 22:12:29,017:15771(0x2b2846e4a700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:42843 sessionTimeout=10000 watcher=0x2b2843e8f6f0 sessionId=0 sessionPasswd=<null> context=0x18174e0 flags=0
> 2014-06-20 22:12:29,017:15771(0x2b284704b700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
> 2014-06-20 22:12:29,017:15771(0x2b284704b700):ZOO_INFO@log_env@716: Client environment:host.name=precise
> 2014-06-20 22:12:29,017:15771(0x2b284704b700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
> 2014-06-20 22:12:29,017:15771(0x2b284704b700):ZOO_INFO@log_env@724: Client environment:os.arch=3.2.0-64-generic
> 2014-06-20 22:12:29,017:15771(0x2b284704b700):ZOO_INFO@log_env@725: Client environment:os.version=#97-Ubuntu SMP Wed Jun 4 22:04:21 UTC 2014
> 2014-06-20 22:12:29,017:15771(0x2b284704b700):ZOO_INFO@log_env@733: Client environment:user.name=(null)
> 2014-06-20 22:12:29,017:15771(0x2b284704b700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
> 2014-06-20 22:12:29,017:15771(0x2b284704b700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_Cr5GZg
> 2014-06-20 22:12:29,017:15771(0x2b284704b700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:42843 sessionTimeout=10000 watcher=0x2b2843e8f6f0 sessionId=0 sessionPasswd=<null> context=0x2b285c017ae0 flags=0
> I0620 22:12:29.018342 15790 log.cpp:238] Attempting to join replica to ZooKeeper group
> I0620 22:12:29.018507 15790 recover.cpp:425] Starting replica recovery
> I0620 22:12:29.018589 15790 recover.cpp:451] Replica is in EMPTY status
> I0620 22:12:29.018929 15790 replica.cpp:638] Replica in EMPTY status received a broadcasted recover request
> I0620 22:12:29.018998 15790 recover.cpp:188] Received a recover response from a replica in EMPTY status
> I0620 22:12:29.019119 15790 recover.cpp:542] Updating replica status to STARTING
> 2014-06-20 22:12:29,020:15771(0x2b284744d700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
> 2014-06-20 22:12:29,020:15771(0x2b284744d700):ZOO_INFO@log_env@716: Client environment:host.name=precise
> 2014-06-20 22:12:29,020:15771(0x2b284744d700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
> 2014-06-20 22:12:29,020:15771(0x2b284744d700):ZOO_INFO@log_env@724: Client environment:os.arch=3.2.0-64-generic
> 2014-06-20 22:12:29,020:15771(0x2b284744d700):ZOO_INFO@log_env@725: Client environment:os.version=#97-Ubuntu SMP Wed Jun 4 22:04:21 UTC 2014
> 2014-06-20 22:12:29,020:15771(0x2b284744d700):ZOO_INFO@log_env@733: Client environment:user.name=(null)
> 2014-06-20 22:12:29,020:15771(0x2b284744d700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
> 2014-06-20 22:12:29,020:15771(0x2b284744d700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_Cr5GZg
> 2014-06-20 22:12:29,020:15771(0x2b284744d700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:42843 sessionTimeout=10000 watcher=0x2b2843e8f6f0 sessionId=0 sessionPasswd=<null> context=0x2b2848016e20 flags=0
> 2014-06-20 22:12:29,021:15771(0x2b284724c700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
> 2014-06-20 22:12:29,021:15771(0x2b284724c700):ZOO_INFO@log_env@716: Client environment:host.name=precise
> 2014-06-20 22:12:29,021:15771(0x2b284724c700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
> 2014-06-20 22:12:29,021:15771(0x2b284724c700):ZOO_INFO@log_env@724: Client environment:os.arch=3.2.0-64-generic
> 2014-06-20 22:12:29,021:15771(0x2b284724c700):ZOO_INFO@log_env@725: Client environment:os.version=#97-Ubuntu SMP Wed Jun 4 22:04:21 UTC 2014
> 2014-06-20 22:12:29,021:15771(0x2b284724c700):ZOO_INFO@log_env@733: Client environment:user.name=(null)
> 2014-06-20 22:12:29,021:15771(0x2b284724c700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
> 2014-06-20 22:12:29,021:15771(0x2b284724c700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_Cr5GZg
> 2014-06-20 22:12:29,021:15771(0x2b284724c700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:42843 sessionTimeout=10000 watcher=0x2b2843e8f6f0 sessionId=0 sessionPasswd=<null> context=0x2b2850012730 flags=0
> I0620 22:12:29.023833 15791 master.cpp:286] Master 20140620-221229-16842879-59864-15771 (precise) started on 127.0.1.1:59864
> I0620 22:12:29.023854 15791 master.cpp:323] Master only allowing authenticated frameworks to register
> I0620 22:12:29.023859 15791 master.cpp:328] Master only allowing authenticated slaves to register
> I0620 22:12:29.023865 15791 credentials.hpp:35] Loading credentials for authentication from '/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_Cr5GZg/credentials'
> I0620 22:12:29.023928 15791 master.cpp:354] Authorization enabled
> I0620 22:12:29.024602 15797 hierarchical_allocator_process.hpp:301] Initializing hierarchical allocator process with master : master@127.0.1.1:59864
> I0620 22:12:29.025117 15791 master.cpp:120] No whitelist given. Advertising offers for all slaves
> I0620 22:12:29.025365 15791 contender.cpp:131] Joining the ZK group
> 2014-06-20 22:12:29,027:15771(0x2b2872ce8700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:42843]
> I0620 22:12:29.028792 15790 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 9.608722ms
> I0620 22:12:29.029295 15790 replica.cpp:320] Persisted replica status to STARTING
> 2014-06-20 22:12:29,029:15771(0x2b28730fe700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:42843]
> 2014-06-20 22:12:29,029:15771(0x2b2873500700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:42843]
> I0620 22:12:29.029839 15790 recover.cpp:451] Replica is in STARTING status
> I0620 22:12:29.030402 15790 replica.cpp:638] Replica in STARTING status received a broadcasted recover request
> I0620 22:12:29.030474 15790 recover.cpp:188] Received a recover response from a replica in STARTING status
> I0620 22:12:29.030580 15790 recover.cpp:542] Updating replica status to VOTING
> 2014-06-20 22:12:29,031:15771(0x2b28726e5700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:42843]
> I0620 22:12:29.047937 15790 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 17.297949ms
> I0620 22:12:29.047969 15790 replica.cpp:320] Persisted replica status to VOTING
> I0620 22:12:29.048028 15790 recover.cpp:556] Successfully joined the Paxos group
> I0620 22:12:29.048099 15790 recover.cpp:440] Recover process terminated
> 2014-06-20 22:12:29,049:15771(0x2b2872ce8700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:42843], sessionId=0x146bcd70e300000, negotiated timeout=10000
> I0620 22:12:29.050029 15796 group.cpp:313] Group process (group(9)@127.0.1.1:59864) connected to ZooKeeper
> I0620 22:12:29.050048 15796 group.cpp:787] Syncing group operations: queue size (joins, cancels, datas) = (1, 0, 0)
> I0620 22:12:29.050056 15796 group.cpp:385] Trying to create path '/znode' in ZooKeeper
> 2014-06-20 22:12:29,055:15771(0x2b28730fe700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:42843], sessionId=0x146bcd70e300001, negotiated timeout=10000
> I0620 22:12:29.055445 15792 group.cpp:313] Group process (group(8)@127.0.1.1:59864) connected to ZooKeeper
> I0620 22:12:29.055462 15792 group.cpp:787] Syncing group operations: queue size (joins, cancels, datas) = (1, 0, 0)
> I0620 22:12:29.055469 15792 group.cpp:385] Trying to create path '/znode/log_replicas' in ZooKeeper
> 2014-06-20 22:12:29,056:15771(0x2b2873500700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:42843], sessionId=0x146bcd70e300002, negotiated timeout=10000
> I0620 22:12:29.056419 15791 group.cpp:313] Group process (group(10)@127.0.1.1:59864) connected to ZooKeeper
> I0620 22:12:29.056437 15791 group.cpp:787] Syncing group operations: queue size (joins, cancels, datas) = (0, 0, 0)
> I0620 22:12:29.056443 15791 group.cpp:385] Trying to create path '/znode' in ZooKeeper
> 2014-06-20 22:12:29,059:15771(0x2b28726e5700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:42843], sessionId=0x146bcd70e300003, negotiated timeout=10000
> I0620 22:12:29.060379 15793 group.cpp:313] Group process (group(7)@127.0.1.1:59864) connected to ZooKeeper
> I0620 22:12:29.060397 15793 group.cpp:787] Syncing group operations: queue size (joins, cancels, datas) = (0, 0, 0)
> I0620 22:12:29.060405 15793 group.cpp:385] Trying to create path '/znode/log_replicas' in ZooKeeper
> I0620 22:12:29.075984 15794 contender.cpp:247] New candidate (id='0') has entered the contest for leadership
> I0620 22:12:29.082536 15791 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
> I0620 22:12:29.082630 15791 detector.cpp:138] Detected a new leader: (id='0')
> I0620 22:12:29.083112 15797 group.cpp:658] Trying to get '/znode/info_0000000000' in ZooKeeper
> I0620 22:12:29.084436 15796 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
> I0620 22:12:29.096356 15797 detector.cpp:382] A new leading master (UPID=master@127.0.1.1:59864) is detected
> I0620 22:12:29.096423 15797 master.cpp:1077] The newly elected leader is master@127.0.1.1:59864 with id 20140620-221229-16842879-59864-15771
> I0620 22:12:29.096436 15797 master.cpp:1090] Elected as the leading master!
> I0620 22:12:29.096443 15797 master.cpp:908] Recovering from registrar
> I0620 22:12:29.096518 15797 registrar.cpp:313] Recovering registrar
> I0620 22:12:29.096776 15797 log.cpp:656] Attempting to start the writer
> I0620 22:12:29.097087 15797 replica.cpp:474] Replica received implicit promise request with proposal 1
> I0620 22:12:29.097465 15793 network.hpp:423] ZooKeeper group memberships changed
> I0620 22:12:29.097839 15793 group.cpp:658] Trying to get '/znode/log_replicas/0000000000' in ZooKeeper
> I0620 22:12:29.099242 15793 network.hpp:461] ZooKeeper group PIDs: { log-replica(185)@127.0.1.1:59864 }
> I0620 22:12:29.107118 15797 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 10.002873ms
> I0620 22:12:29.107157 15797 replica.cpp:342] Persisted promised to 1
> I0620 22:12:29.107345 15797 coordinator.cpp:230] Coordinator attemping to fill missing position
> I0620 22:12:29.107666 15797 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2
> I0620 22:12:29.116905 15797 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 9.215833ms
> I0620 22:12:29.116940 15797 replica.cpp:676] Persisted action at 0
> I0620 22:12:29.117200 15797 replica.cpp:508] Replica received write request for position 0
> I0620 22:12:29.117228 15797 leveldb.cpp:438] Reading position from leveldb took 13095ns
> I0620 22:12:29.127976 15797 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 10.728783ms
> I0620 22:12:29.128164 15797 replica.cpp:676] Persisted action at 0
> I0620 22:12:29.133956 15790 replica.cpp:655] Replica received learned notice for position 0
> I0620 22:12:29.142964 15790 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 8.975834ms
> I0620 22:12:29.143003 15790 replica.cpp:676] Persisted action at 0
> I0620 22:12:29.143014 15790 replica.cpp:661] Replica learned NOP action at position 0
> I0620 22:12:29.143213 15790 log.cpp:672] Writer started with ending position 0
> I0620 22:12:29.143463 15790 leveldb.cpp:438] Reading position from leveldb took 15413ns
> I0620 22:12:29.149883 15790 registrar.cpp:346] Successfully fetched the registry (0B)
> I0620 22:12:29.149911 15790 registrar.cpp:422] Attempting to update the 'registry'
> I0620 22:12:29.151124 15790 log.cpp:680] Attempting to append 120 bytes to the log
> I0620 22:12:29.151171 15790 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1
> I0620 22:12:29.151393 15790 replica.cpp:508] Replica received write request for position 1
> I0620 22:12:29.160166 15790 leveldb.cpp:343] Persisting action (137 bytes) to leveldb took 8.747107ms
> I0620 22:12:29.160344 15790 replica.cpp:676] Persisted action at 1
> I0620 22:12:29.165982 15796 replica.cpp:655] Replica received learned notice for position 1
> I0620 22:12:29.175163 15796 leveldb.cpp:343] Persisting action (139 bytes) to leveldb took 9.15178ms
> I0620 22:12:29.175201 15796 replica.cpp:676] Persisted action at 1
> I0620 22:12:29.175211 15796 replica.cpp:661] Replica learned APPEND action at position 1
> I0620 22:12:29.175534 15796 registrar.cpp:479] Successfully updated 'registry'
> I0620 22:12:29.175575 15796 registrar.cpp:372] Successfully recovered registrar
> I0620 22:12:29.175613 15796 log.cpp:699] Attempting to truncate the log to 1
> I0620 22:12:29.175686 15796 master.cpp:935] Recovered 0 slaves from the Registry (84B) ; allowing 10mins for slaves to re-register
> I0620 22:12:29.175726 15796 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2
> I0620 22:12:29.175963 15796 replica.cpp:508] Replica received write request for position 2
> I0620 22:12:29.179386 15771 sched.cpp:139] Version: 0.20.0
> 2014-06-20 22:12:29,179:15771(0x2b2846847700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
> 2014-06-20 22:12:29,180:15771(0x2b2846847700):ZOO_INFO@log_env@716: Client environment:host.name=precise
> 2014-06-20 22:12:29,180:15771(0x2b2846847700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
> 2014-06-20 22:12:29,180:15771(0x2b2846847700):ZOO_INFO@log_env@724: Client environment:os.arch=3.2.0-64-generic
> 2014-06-20 22:12:29,180:15771(0x2b2846847700):ZOO_INFO@log_env@725: Client environment:os.version=#97-Ubuntu SMP Wed Jun 4 22:04:21 UTC 2014
> 2014-06-20 22:12:29,180:15771(0x2b2846847700):ZOO_INFO@log_env@733: Client environment:user.name=(null)
> 2014-06-20 22:12:29,180:15771(0x2b2846847700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
> 2014-06-20 22:12:29,180:15771(0x2b2846847700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_Cr5GZg
> 2014-06-20 22:12:29,180:15771(0x2b2846847700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:42843 sessionTimeout=10000 watcher=0x2b2843e8f6f0 sessionId=0 sessionPasswd=<null> context=0x2b284c0620a0 flags=0
> 2014-06-20 22:12:29,180:15771(0x2b284764e700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
> 2014-06-20 22:12:29,180:15771(0x2b284764e700):ZOO_INFO@log_env@716: Client environment:host.name=precise
> 2014-06-20 22:12:29,180:15771(0x2b284764e700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
> 2014-06-20 22:12:29,180:15771(0x2b284764e700):ZOO_INFO@log_env@724: Client environment:os.arch=3.2.0-64-generic
> 2014-06-20 22:12:29,180:15771(0x2b284764e700):ZOO_INFO@log_env@725: Client environment:os.version=#97-Ubuntu SMP Wed Jun 4 22:04:21 UTC 2014
> 2014-06-20 22:12:29,181:15771(0x2b284764e700):ZOO_INFO@log_env@733: Client environment:user.name=(null)
> 2014-06-20 22:12:29,181:15771(0x2b284764e700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
> 2014-06-20 22:12:29,181:15771(0x2b284764e700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_Cr5GZg
> 2014-06-20 22:12:29,181:15771(0x2b284764e700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:42843 sessionTimeout=10000 watcher=0x2b2843e8f6f0 sessionId=0 sessionPasswd=<null> context=0x2b2864062580 flags=0
> I0620 22:12:29.179656 15795 slave.cpp:165] Slave started on 29)@127.0.1.1:59864
> I0620 22:12:29.181361 15795 credentials.hpp:35] Loading credentials for authentication from '/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_jFdang/credential'
> I0620 22:12:29.181431 15795 slave.cpp:265] Slave using credential for: test-principal
> I0620 22:12:29.181566 15795 slave.cpp:278] Slave resources: cpus(*):2; mem(*):1024; disk(*):25116; ports(*):[31000-32000]
> I0620 22:12:29.181632 15795 slave.cpp:306] Slave hostname: precise
> I0620 22:12:29.181643 15795 slave.cpp:307] Slave checkpoint: false
> I0620 22:12:29.182442 15795 state.cpp:33] Recovering state from '/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_jFdang/meta'
> I0620 22:12:29.182555 15795 status_update_manager.cpp:193] Recovering status update manager
> I0620 22:12:29.182664 15795 slave.cpp:3112] Finished recovery
> 2014-06-20 22:12:29,184:15771(0x2b2874343700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:42843]
> I0620 22:12:29.185120 15796 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 9.136002ms
> I0620 22:12:29.185309 15796 replica.cpp:676] Persisted action at 2
> I0620 22:12:29.185518 15796 replica.cpp:655] Replica received learned notice for position 2
> 2014-06-20 22:12:29,186:15771(0x2b2873f41700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:42843]
> 2014-06-20 22:12:29,190:15771(0x2b2874343700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:42843], sessionId=0x146bcd70e300004, negotiated timeout=10000
> I0620 22:12:29.191119 15795 group.cpp:313] Group process (group(12)@127.0.1.1:59864) connected to ZooKeeper
> I0620 22:12:29.191140 15795 group.cpp:787] Syncing group operations: queue size (joins, cancels, datas) = (0, 0, 0)
> I0620 22:12:29.191148 15795 group.cpp:385] Trying to create path '/znode' in ZooKeeper
> I0620 22:12:29.198513 15796 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 12.972967ms
> I0620 22:12:29.198580 15796 leveldb.cpp:401] Deleting ~1 keys from leveldb took 30909ns
> I0620 22:12:29.198593 15796 replica.cpp:676] Persisted action at 2
> I0620 22:12:29.198603 15796 replica.cpp:661] Replica learned TRUNCATE action at position 2
> 2014-06-20 22:12:29,205:15771(0x2b2873f41700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:42843], sessionId=0x146bcd70e300005, negotiated timeout=10000
> I0620 22:12:29.206363 15796 group.cpp:313] Group process (group(11)@127.0.1.1:59864) connected to ZooKeeper
> I0620 22:12:29.206383 15796 group.cpp:787] Syncing group operations: queue size (joins, cancels, datas) = (0, 0, 0)
> I0620 22:12:29.206390 15796 group.cpp:385] Trying to create path '/znode' in ZooKeeper
> I0620 22:12:29.207442 15795 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
> I0620 22:12:29.207512 15795 detector.cpp:138] Detected a new leader: (id='0')
> I0620 22:12:29.207624 15795 group.cpp:658] Trying to get '/znode/info_0000000000' in ZooKeeper
> I0620 22:12:29.209198 15795 detector.cpp:382] A new leading master (UPID=master@127.0.1.1:59864) is detected
> I0620 22:12:29.209259 15795 sched.cpp:235] New master detected at master@127.0.1.1:59864
> I0620 22:12:29.209275 15795 sched.cpp:285] Authenticating with master master@127.0.1.1:59864
> I0620 22:12:29.209381 15795 authenticatee.hpp:128] Creating new client SASL connection
> I0620 22:12:29.209568 15795 master.cpp:3457] Authenticating scheduler-3d720a51-c2cb-4670-a37e-1fe811c53a07@127.0.1.1:59864
> I0620 22:12:29.209663 15795 authenticator.hpp:156] Creating new server SASL connection
> I0620 22:12:29.209835 15795 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
> I0620 22:12:29.209853 15795 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0620 22:12:29.209877 15795 authenticator.hpp:262] Received SASL authentication start
> I0620 22:12:29.209923 15795 authenticator.hpp:384] Authentication requires more steps
> I0620 22:12:29.209947 15795 authenticatee.hpp:265] Received SASL authentication step
> I0620 22:12:29.209980 15795 authenticator.hpp:290] Received SASL authentication step
> I0620 22:12:29.210003 15795 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'precise' server FQDN: 'precise' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0620 22:12:29.210011 15795 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
> I0620 22:12:29.210021 15795 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0620 22:12:29.210029 15795 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'precise' server FQDN: 'precise' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0620 22:12:29.210034 15795 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0620 22:12:29.210038 15795 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0620 22:12:29.210049 15795 authenticator.hpp:376] Authentication success
> I0620 22:12:29.210074 15795 authenticatee.hpp:305] Authentication success
> I0620 22:12:29.210095 15795 master.cpp:3497] Successfully authenticated principal 'test-principal' at scheduler-3d720a51-c2cb-4670-a37e-1fe811c53a07@127.0.1.1:59864
> I0620 22:12:29.210160 15795 sched.cpp:359] Successfully authenticated with master master@127.0.1.1:59864
> I0620 22:12:29.210172 15795 sched.cpp:478] Sending registration request to master@127.0.1.1:59864
> I0620 22:12:29.210229 15795 master.cpp:1196] Received registration request from scheduler-3d720a51-c2cb-4670-a37e-1fe811c53a07@127.0.1.1:59864
> I0620 22:12:29.210250 15795 master.cpp:1156] Authorizing framework principal 'test-principal' to receive offers for role '*'
> I0620 22:12:29.210372 15795 master.cpp:1255] Registering framework 20140620-221229-16842879-59864-15771-0000 at scheduler-3d720a51-c2cb-4670-a37e-1fe811c53a07@127.0.1.1:59864
> I0620 22:12:29.210469 15795 sched.cpp:409] Framework registered with 20140620-221229-16842879-59864-15771-0000
> I0620 22:12:29.210489 15795 sched.cpp:423] Scheduler::registered took 8462ns
> I0620 22:12:29.210521 15795 hierarchical_allocator_process.hpp:331] Added framework 20140620-221229-16842879-59864-15771-0000
> I0620 22:12:29.210530 15795 hierarchical_allocator_process.hpp:724] No resources available to allocate!
> I0620 22:12:29.210536 15795 hierarchical_allocator_process.hpp:686] Performed allocation for 0 slaves in 5801ns
> I0620 22:12:29.211791 15796 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
> I0620 22:12:29.211848 15796 detector.cpp:138] Detected a new leader: (id='0')
> I0620 22:12:29.211936 15796 group.cpp:658] Trying to get '/znode/info_0000000000' in ZooKeeper
> I0620 22:12:29.212857 15796 detector.cpp:382] A new leading master (UPID=master@127.0.1.1:59864) is detected
> I0620 22:12:29.212914 15796 slave.cpp:581] New master detected at master@127.0.1.1:59864
> I0620 22:12:29.212936 15796 slave.cpp:657] Authenticating with master master@127.0.1.1:59864
> I0620 22:12:29.212971 15796 slave.cpp:630] Detecting new master
> I0620 22:12:29.213006 15796 status_update_manager.cpp:167] New master detected at master@127.0.1.1:59864
> I0620 22:12:29.213034 15796 authenticatee.hpp:128] Creating new client SASL connection
> I0620 22:12:29.213161 15796 master.cpp:3457] Authenticating slave(29)@127.0.1.1:59864
> I0620 22:12:29.213234 15796 authenticator.hpp:156] Creating new server SASL connection
> I0620 22:12:29.213328 15796 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
> I0620 22:12:29.213345 15796 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0620 22:12:29.213366 15796 authenticator.hpp:262] Received SASL authentication start
> I0620 22:12:29.213397 15796 authenticator.hpp:384] Authentication requires more steps
> I0620 22:12:29.213420 15796 authenticatee.hpp:265] Received SASL authentication step
> I0620 22:12:29.213448 15796 authenticator.hpp:290] Received SASL authentication step
> I0620 22:12:29.213460 15796 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'precise' server FQDN: 'precise' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0620 22:12:29.213466 15796 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
> I0620 22:12:29.213474 15796 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0620 22:12:29.213481 15796 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'precise' server FQDN: 'precise' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0620 22:12:29.213487 15796 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0620 22:12:29.213491 15796 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0620 22:12:29.213500 15796 authenticator.hpp:376] Authentication success
> I0620 22:12:29.213523 15796 authenticatee.hpp:305] Authentication success
> I0620 22:12:29.213543 15796 master.cpp:3497] Successfully authenticated principal 'test-principal' at slave(29)@127.0.1.1:59864
> I0620 22:12:29.213600 15796 slave.cpp:714] Successfully authenticated with master master@127.0.1.1:59864
> I0620 22:12:29.213650 15796 slave.cpp:952] Will retry registration in 16.997934ms if necessary
> I0620 22:12:29.214143 15794 master.cpp:2736] Registering slave at slave(29)@127.0.1.1:59864 (precise) with id 20140620-221229-16842879-59864-15771-0
> I0620 22:12:29.214293 15794 registrar.cpp:422] Attempting to update the 'registry'
> I0620 22:12:29.215993 15793 log.cpp:680] Attempting to append 295 bytes to the log
> I0620 22:12:29.216048 15793 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3
> I0620 22:12:29.216550 15793 replica.cpp:508] Replica received write request for position 3
> I0620 22:12:29.225689 15793 leveldb.cpp:343] Persisting action (314 bytes) to leveldb took 9.110879ms
> I0620 22:12:29.225765 15793 replica.cpp:676] Persisted action at 3
> I0620 22:12:29.225973 15793 replica.cpp:655] Replica received learned notice for position 3
> I0620 22:12:29.231385 15791 slave.cpp:952] Will retry registration in 39.831813ms if necessary
> I0620 22:12:29.231457 15791 master.cpp:2724] Ignoring register slave message from slave(29)@127.0.1.1:59864 (precise) as admission is already in progress
> I0620 22:12:29.234421 15793 leveldb.cpp:343] Persisting action (316 bytes) to leveldb took 8.425837ms
> I0620 22:12:29.234449 15793 replica.cpp:676] Persisted action at 3
> I0620 22:12:29.234458 15793 replica.cpp:661] Replica learned APPEND action at position 3
> I0620 22:12:29.234796 15793 registrar.cpp:479] Successfully updated 'registry'
> I0620 22:12:29.234876 15793 log.cpp:699] Attempting to truncate the log to 3
> I0620 22:12:29.234933 15793 master.cpp:2776] Registered slave 20140620-221229-16842879-59864-15771-0 at slave(29)@127.0.1.1:59864 (precise)
> I0620 22:12:29.234947 15793 master.cpp:3923] Adding slave 20140620-221229-16842879-59864-15771-0 at slave(29)@127.0.1.1:59864 (precise) with cpus(*):2; mem(*):1024; disk(*):25116; ports(*):[31000-32000]
> I0620 22:12:29.235056 15793 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4
> I0620 22:12:29.235136 15793 slave.cpp:748] Registered with master master@127.0.1.1:59864; given slave ID 20140620-221229-16842879-59864-15771-0
> I0620 22:12:29.235203 15793 hierarchical_allocator_process.hpp:444] Added slave 20140620-221229-16842879-59864-15771-0 (precise) with cpus(*):2; mem(*):1024; disk(*):25116; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):25116; ports(*):[31000-32000] available)
> I0620 22:12:29.235267 15793 hierarchical_allocator_process.hpp:750] Offering cpus(*):2; mem(*):1024; disk(*):25116; ports(*):[31000-32000] on slave 20140620-221229-16842879-59864-15771-0 to framework 20140620-221229-16842879-59864-15771-0000
> I0620 22:12:29.235359 15793 hierarchical_allocator_process.hpp:706] Performed allocation for slave 20140620-221229-16842879-59864-15771-0 in 126210ns
> I0620 22:12:29.235460 15793 master.hpp:789] Adding offer 20140620-221229-16842879-59864-15771-0 with resources cpus(*):2; mem(*):1024; disk(*):25116; ports(*):[31000-32000] on slave 20140620-221229-16842879-59864-15771-0 (precise)
> I0620 22:12:29.235501 15793 master.cpp:3404] Sending 1 offers to framework 20140620-221229-16842879-59864-15771-0000
> I0620 22:12:29.235810 15793 sched.cpp:546] Scheduler::resourceOffers took 181453ns
> I0620 22:12:29.236023 15793 master.hpp:799] Removing offer 20140620-221229-16842879-59864-15771-0 with resources cpus(*):2; mem(*):1024; disk(*):25116; ports(*):[31000-32000] on slave 20140620-221229-16842879-59864-15771-0 (precise)
> I0620 22:12:29.236073 15793 master.cpp:2080] Processing reply for offers: [ 20140620-221229-16842879-59864-15771-0 ] on slave 20140620-221229-16842879-59864-15771-0 at slave(29)@127.0.1.1:59864 (precise) for framework 20140620-221229-16842879-59864-15771-0000
> I0620 22:12:29.236101 15793 master.cpp:2166] Authorizing framework principal 'test-principal' to launch task 0 as user 'jenkins'
> I0620 22:12:29.236491 15793 master.hpp:761] Adding task 0 with resources cpus(*):1; mem(*):500 on slave 20140620-221229-16842879-59864-15771-0 (precise)
> I0620 22:12:29.236518 15793 master.cpp:2232] Launching task 0 of framework 20140620-221229-16842879-59864-15771-0000 with resources cpus(*):1; mem(*):500 on slave 20140620-221229-16842879-59864-15771-0 at slave(29)@127.0.1.1:59864 (precise)
> I0620 22:12:29.236650 15793 replica.cpp:508] Replica received write request for position 4
> I0620 22:12:29.236804 15791 slave.cpp:983] Got assigned task 0 for framework 20140620-221229-16842879-59864-15771-0000
> I0620 22:12:29.236945 15792 hierarchical_allocator_process.hpp:546] Framework 20140620-221229-16842879-59864-15771-0000 left cpus(*):1; mem(*):524; disk(*):25116; ports(*):[31000-32000] unused on slave 20140620-221229-16842879-59864-15771-0
> I0620 22:12:29.237021 15792 hierarchical_allocator_process.hpp:588] Framework 20140620-221229-16842879-59864-15771-0000 filtered slave 20140620-221229-16842879-59864-15771-0 for 5secs
> I0620 22:12:29.237287 15791 slave.cpp:1093] Launching task 0 for framework 20140620-221229-16842879-59864-15771-0000
> I0620 22:12:29.240905 15791 exec.cpp:131] Version: 0.20.0
> I0620 22:12:29.241333 15790 exec.cpp:181] Executor started at: executor(1)@127.0.1.1:59864 with pid 15771
> I0620 22:12:29.241606 15791 slave.cpp:1203] Queuing task '0' for executor default of framework '20140620-221229-16842879-59864-15771-0000
> I0620 22:12:29.241992 15791 slave.cpp:542] Successfully attached file '/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_jFdang/slaves/20140620-221229-16842879-59864-15771-0/frameworks/20140620-221229-16842879-59864-15771-0000/executors/default/runs/1b52f316-bf41-4c84-b875-bbbe336b91fa'
> I0620 22:12:29.242290 15791 slave.cpp:1714] Got registration for executor 'default' of framework 20140620-221229-16842879-59864-15771-0000
> I0620 22:12:29.242789 15792 exec.cpp:205] Executor registered on slave 20140620-221229-16842879-59864-15771-0
> I0620 22:12:29.244197 15792 exec.cpp:217] Executor::registered took 30105ns
> I0620 22:12:29.244571 15791 slave.cpp:1833] Flushing queued task 0 for executor 'default' of framework 20140620-221229-16842879-59864-15771-0000
> I0620 22:12:29.245123 15795 exec.cpp:292] Executor asked to run task '0'
> I0620 22:12:29.245187 15795 exec.cpp:301] Executor::launchTask took 45150ns
> I0620 22:12:29.246320 15795 exec.cpp:524] Executor sending status update TASK_RUNNING (UUID: 132905cf-168a-48a5-9ad5-5381463e2e6e) for task 0 of framework 20140620-221229-16842879-59864-15771-0000
> I0620 22:12:29.246585 15791 slave.cpp:2449] Monitoring executor 'default' of framework '20140620-221229-16842879-59864-15771-0000' in container '1b52f316-bf41-4c84-b875-bbbe336b91fa'
> I0620 22:12:29.247234 15791 slave.cpp:2068] Handling status update TASK_RUNNING (UUID: 132905cf-168a-48a5-9ad5-5381463e2e6e) for task 0 of framework 20140620-221229-16842879-59864-15771-0000 from executor(1)@127.0.1.1:59864
> I0620 22:12:29.247689 15792 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: 132905cf-168a-48a5-9ad5-5381463e2e6e) for task 0 of framework 20140620-221229-16842879-59864-15771-0000
> I0620 22:12:29.247714 15792 status_update_manager.cpp:499] Creating StatusUpdate stream for task 0 of framework 20140620-221229-16842879-59864-15771-0000
> I0620 22:12:29.247827 15792 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: 132905cf-168a-48a5-9ad5-5381463e2e6e) for task 0 of framework 20140620-221229-16842879-59864-15771-0000 to master@127.0.1.1:59864
> I0620 22:12:29.248124 15792 master.cpp:3062] Status update TASK_RUNNING (UUID: 132905cf-168a-48a5-9ad5-5381463e2e6e) for task 0 of framework 20140620-221229-16842879-59864-15771-0000 from slave 20140620-221229-16842879-59864-15771-0 at slave(29)@127.0.1.1:59864 (precise)
> I0620 22:12:29.248641 15792 master.cpp:610] Master terminating
> I0620 22:12:29.248975 15792 master.hpp:779] Removing task 0 with resources cpus(*):1; mem(*):500 on slave 20140620-221229-16842879-59864-15771-0 (precise)
> I0620 22:12:29.248380 15794 sched.cpp:637] Scheduler::statusUpdate took 30965ns
> W0620 22:12:29.249487 15792 master.cpp:4209] Removing task 0 of framework 20140620-221229-16842879-59864-15771-0000 and slave 20140620-221229-16842879-59864-15771-0 in non-terminal state TASK_RUNNING
> I0620 22:12:29.249703 15794 hierarchical_allocator_process.hpp:635] Recovered cpus(*):1; mem(*):500 (total allocatable: cpus(*):2; mem(*):1024; disk(*):25116; ports(*):[31000-32000]) on slave 20140620-221229-16842879-59864-15771-0 from framework 20140620-221229-16842879-59864-15771-0000
> 2014-06-20 22:12:29,251:15771(0x2b2846641f80):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x146bcd70e300001 to [127.0.0.1:42843]
> 2014-06-20 22:12:29,253:15771(0x2b2846641f80):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x146bcd70e300003 to [127.0.0.1:42843]
> I0620 22:12:29.255873 15793 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 19.142912ms
> I0620 22:12:29.256362 15793 replica.cpp:676] Persisted action at 4
> I0620 22:12:29.259801 15771 contender.cpp:186] Now cancelling the membership: 0
> 2014-06-20 22:12:29,260:15771(0x2b2846641f80):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x146bcd70e300000 to [127.0.0.1:42843]
> 2014-06-20 22:12:29,260:15771(0x2b2846641f80):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x146bcd70e300002 to [127.0.0.1:42843]
> I0620 22:12:29.263706 15791 slave.cpp:2311] master@127.0.1.1:59864 exited
> W0620 22:12:29.264472 15791 slave.cpp:2314] Master disconnected! Waiting for a new master to be elected
> I0620 22:12:29.264873 15791 slave.cpp:2226] Status update manager successfully handled status update TASK_RUNNING (UUID: 132905cf-168a-48a5-9ad5-5381463e2e6e) for task 0 of framework 20140620-221229-16842879-59864-15771-0000
> I0620 22:12:29.265123 15791 slave.cpp:2232] Sending acknowledgement for status update TASK_RUNNING (UUID: 132905cf-168a-48a5-9ad5-5381463e2e6e) for task 0 of framework 20140620-221229-16842879-59864-15771-0000 to executor(1)@127.0.1.1:59864
> I0620 22:12:29.265492 15790 exec.cpp:338] Executor received status update acknowledgement 132905cf-168a-48a5-9ad5-5381463e2e6e for task 0 of framework 20140620-221229-16842879-59864-15771-0000
> I0620 22:12:29.276870 15792 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
> I0620 22:12:29.277102 15792 detector.cpp:126] The current leader (id=0) is lost
> I0620 22:12:29.277117 15792 detector.cpp:138] Detected a new leader: None
> I0620 22:12:29.277495 15795 slave.cpp:626] Lost leading master
> I0620 22:12:29.277513 15795 slave.cpp:630] Detecting new master
> I0620 22:12:29.278142 15797 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
> I0620 22:12:29.278192 15797 detector.cpp:126] The current leader (id=0) is lost
> I0620 22:12:29.278200 15797 detector.cpp:138] Detected a new leader: None
> I0620 22:12:29.278306 15797 sched.cpp:229] Scheduler::disconnected took 7760ns
> I0620 22:12:29.278318 15797 sched.cpp:251] No master detected
> I0620 22:12:29.291004 15771 leveldb.cpp:176] Opened db in 29.746546ms
> I0620 22:12:29.307518 15771 leveldb.cpp:183] Compacted db in 16.068905ms
> I0620 22:12:29.307977 15771 leveldb.cpp:198] Created db iterator in 7322ns
> I0620 22:12:29.308254 15771 leveldb.cpp:204] Seeked to beginning of db in 12436ns
> I0620 22:12:29.308590 15771 leveldb.cpp:273] Iterated through 5 keys in the db in 60139ns
> I0620 22:12:29.308857 15771 replica.cpp:741] Replica recovered with log positions 1 -> 4 with 0 holes and 1 unlearned
> 2014-06-20 22:12:29,309:15771(0x2b2846847700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
> 2014-06-20 22:12:29,309:15771(0x2b2846847700):ZOO_INFO@log_env@716: Client environment:host.name=precise
> 2014-06-20 22:12:29,309:15771(0x2b2846847700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
> 2014-06-20 22:12:29,309:15771(0x2b2846847700):ZOO_INFO@log_env@724: Client environment:os.arch=3.2.0-64-generic
> 2014-06-20 22:12:29,309:15771(0x2b2846847700):ZOO_INFO@log_env@725: Client environment:os.version=#97-Ubuntu SMP Wed Jun 4 22:04:21 UTC 2014
> 2014-06-20 22:12:29,309:15771(0x2b2846847700):ZOO_INFO@log_env@733: Client environment:user.name=(null)
> 2014-06-20 22:12:29,309:15771(0x2b2846847700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
> 2014-06-20 22:12:29,309:15771(0x2b2846847700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_Cr5GZg
> 2014-06-20 22:12:29,309:15771(0x2b2846847700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:42843 sessionTimeout=10000 watcher=0x2b2843e8f6f0 sessionId=0 sessionPasswd=<null> context=0x2b2864066890 flags=0
> 2014-06-20 22:12:29,310:15771(0x2b2846c49700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
> 2014-06-20 22:12:29,310:15771(0x2b2846c49700):ZOO_INFO@log_env@716: Client environment:host.name=precise
> 2014-06-20 22:12:29,310:15771(0x2b2846c49700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
> 2014-06-20 22:12:29,310:15771(0x2b2846c49700):ZOO_INFO@log_env@724: Client environment:os.arch=3.2.0-64-generic
> 2014-06-20 22:12:29,310:15771(0x2b2846c49700):ZOO_INFO@log_env@725: Client environment:os.version=#97-Ubuntu SMP Wed Jun 4 22:04:21 UTC 2014
> 2014-06-20 22:12:29,310:15771(0x2b2846c49700):ZOO_INFO@log_env@733: Client environment:user.name=(null)
> 2014-06-20 22:12:29,310:15771(0x2b2846c49700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
> 2014-06-20 22:12:29,310:15771(0x2b2846c49700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_Cr5GZg
> 2014-06-20 22:12:29,310:15771(0x2b2846c49700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:42843 sessionTimeout=10000 watcher=0x2b2843e8f6f0 sessionId=0 sessionPasswd=<null> context=0x2b28600471a0 flags=0
> I0620 22:12:29.311206 15791 log.cpp:238] Attempting to join replica to ZooKeeper group
> I0620 22:12:29.312000 15791 recover.cpp:425] Starting replica recovery
> 2014-06-20 22:12:29,312:15771(0x2b2846a48700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
> 2014-06-20 22:12:29,312:15771(0x2b2846a48700):ZOO_INFO@log_env@716: Client environment:host.name=precise
> 2014-06-20 22:12:29,312:15771(0x2b2846a48700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
> 2014-06-20 22:12:29,312:15771(0x2b2846a48700):ZOO_INFO@log_env@724: Client environment:os.arch=3.2.0-64-generic
> 2014-06-20 22:12:29,312:15771(0x2b2846a48700):ZOO_INFO@log_env@725: Client environment:os.version=#97-Ubuntu SMP Wed Jun 4 22:04:21 UTC 2014
> 2014-06-20 22:12:29,312:15771(0x2b2846a48700):ZOO_INFO@log_env@733: Client environment:user.name=(null)
> 2014-06-20 22:12:29,312:15771(0x2b2846a48700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
> 2014-06-20 22:12:29,312:15771(0x2b2846a48700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_Cr5GZg
> 2014-06-20 22:12:29,312:15771(0x2b2846a48700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:42843 sessionTimeout=10000 watcher=0x2b2843e8f6f0 sessionId=0 sessionPasswd=<null> context=0x2b286800dbb0 flags=0
> 2014-06-20 22:12:29,312:15771(0x2b284744d700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
> 2014-06-20 22:12:29,312:15771(0x2b284744d700):ZOO_INFO@log_env@716: Client environment:host.name=precise
> 2014-06-20 22:12:29,312:15771(0x2b284744d700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
> 2014-06-20 22:12:29,312:15771(0x2b284744d700):ZOO_INFO@log_env@724: Client environment:os.arch=3.2.0-64-generic
> 2014-06-20 22:12:29,312:15771(0x2b284744d700):ZOO_INFO@log_env@725: Client environment:os.version=#97-Ubuntu SMP Wed Jun 4 22:04:21 UTC 2014
> 2014-06-20 22:12:29,312:15771(0x2b284744d700):ZOO_INFO@log_env@733: Client environment:user.name=(null)
> 2014-06-20 22:12:29,312:15771(0x2b284744d700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
> 2014-06-20 22:12:29,312:15771(0x2b284744d700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_Cr5GZg
> 2014-06-20 22:12:29,312:15771(0x2b284744d700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:42843 sessionTimeout=10000 watcher=0x2b2843e8f6f0 sessionId=0 sessionPasswd=<null> context=0x2b286801c8c0 flags=0
> I0620 22:12:29.312999 15797 recover.cpp:451] Replica is in VOTING status
> I0620 22:12:29.313045 15797 recover.cpp:440] Recover process terminated
> I0620 22:12:29.313536 15795 master.cpp:286] Master 20140620-221229-16842879-59864-15771 (precise) started on 127.0.1.1:59864
> I0620 22:12:29.313559 15795 master.cpp:323] Master only allowing authenticated frameworks to register
> I0620 22:12:29.313565 15795 master.cpp:328] Master only allowing authenticated slaves to register
> I0620 22:12:29.313571 15795 credentials.hpp:35] Loading credentials for authentication from '/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_Cr5GZg/credentials'
> I0620 22:12:29.313642 15795 master.cpp:354] Authorization enabled
> I0620 22:12:29.314226 15795 master.cpp:120] No whitelist given. Advertising offers for all slaves
> I0620 22:12:29.314483 15795 hierarchical_allocator_process.hpp:301] Initializing hierarchical allocator process with master : master@127.0.1.1:59864
> I0620 22:12:29.314532 15795 contender.cpp:131] Joining the ZK group
> 2014-06-20 22:12:29,315:15771(0x2b2872efd700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:42843]
> 2014-06-20 22:12:29,316:15771(0x2b2872ae7700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:42843]
> 2014-06-20 22:12:29,317:15771(0x2b28728e6700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:42843]
> 2014-06-20 22:12:29,321:15771(0x2b28732ff700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:42843]
> 2014-06-20 22:12:29,323:15771(0x2b2872efd700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:42843], sessionId=0x146bcd70e300006, negotiated timeout=10000
> I0620 22:12:29.324039 15795 group.cpp:313] Group process (group(16)@127.0.1.1:59864) connected to ZooKeeper
> I0620 22:12:29.324064 15795 group.cpp:787] Syncing group operations: queue size (joins, cancels, datas) = (0, 0, 0)
> I0620 22:12:29.324071 15795 group.cpp:385] Trying to create path '/znode' in ZooKeeper
> 2014-06-20 22:12:29,327:15771(0x2b2872ae7700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:42843], sessionId=0x146bcd70e300007, negotiated timeout=10000
> I0620 22:12:29.328102 15797 group.cpp:313] Group process (group(15)@127.0.1.1:59864) connected to ZooKeeper
> I0620 22:12:29.328124 15797 group.cpp:787] Syncing group operations: queue size (joins, cancels, datas) = (1, 0, 0)
> I0620 22:12:29.328130 15797 group.cpp:385] Trying to create path '/znode' in ZooKeeper
> 2014-06-20 22:12:29,328:15771(0x2b28728e6700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:42843], sessionId=0x146bcd70e300008, negotiated timeout=10000
> I0620 22:12:29.328908 15792 group.cpp:313] Group process (group(14)@127.0.1.1:59864) connected to ZooKeeper
> I0620 22:12:29.328927 15792 group.cpp:787] Syncing group operations: queue size (joins, cancels, datas) = (1, 0, 0)
> I0620 22:12:29.328933 15792 group.cpp:385] Trying to create path '/znode/log_replicas' in ZooKeeper
> 2014-06-20 22:12:29,341:15771(0x2b28732ff700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:42843], sessionId=0x146bcd70e300009, negotiated timeout=10000
> I0620 22:12:29.342126 15795 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
> I0620 22:12:29.342445 15796 group.cpp:313] Group process (group(13)@127.0.1.1:59864) connected to ZooKeeper
> I0620 22:12:29.342464 15796 group.cpp:787] Syncing group operations: queue size (joins, cancels, datas) = (0, 0, 0)
> I0620 22:12:29.342473 15796 group.cpp:385] Trying to create path '/znode/log_replicas' in ZooKeeper
> I0620 22:12:29.363756 15795 contender.cpp:247] New candidate (id='2') has entered the contest for leadership
> I0620 22:12:29.365463 15796 network.hpp:423] ZooKeeper group memberships changed
> I0620 22:12:29.365558 15796 group.cpp:658] Trying to get '/znode/log_replicas/0000000001' in ZooKeeper
> I0620 22:12:29.366583 15791 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
> I0620 22:12:29.366644 15791 detector.cpp:138] Detected a new leader: (id='2')
> I0620 22:12:29.367019 15791 group.cpp:658] Trying to get '/znode/info_0000000002' in ZooKeeper
> I0620 22:12:29.367941 15794 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
> I0620 22:12:29.367998 15794 detector.cpp:138] Detected a new leader: (id='2')
> I0620 22:12:29.368088 15794 group.cpp:658] Trying to get '/znode/info_0000000002' in ZooKeeper
> I0620 22:12:29.369071 15790 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
> I0620 22:12:29.369397 15790 detector.cpp:138] Detected a new leader: (id='2')
> I0620 22:12:29.369505 15790 group.cpp:658] Trying to get '/znode/info_0000000002' in ZooKeeper
> I0620 22:12:29.370779 15797 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
> I0620 22:12:29.371628 15796 network.hpp:461] ZooKeeper group PIDs: { log-replica(186)@127.0.1.1:59864 }
> I0620 22:12:29.372532 15791 detector.cpp:382] A new leading master (UPID=master@127.0.1.1:59864) is detected
> I0620 22:12:29.372588 15791 master.cpp:1077] The newly elected leader is master@127.0.1.1:59864 with id 20140620-221229-16842879-59864-15771
> I0620 22:12:29.372601 15791 master.cpp:1090] Elected as the leading master!
> I0620 22:12:29.372607 15791 master.cpp:908] Recovering from registrar
> I0620 22:12:29.372665 15791 registrar.cpp:313] Recovering registrar
> I0620 22:12:29.372895 15791 log.cpp:656] Attempting to start the writer
> I0620 22:12:29.373225 15791 replica.cpp:474] Replica received implicit promise request with proposal 2
> I0620 22:12:29.374613 15794 detector.cpp:382] A new leading master (UPID=master@127.0.1.1:59864) is detected
> I0620 22:12:29.374676 15794 sched.cpp:235] New master detected at master@127.0.1.1:59864
> I0620 22:12:29.374692 15794 sched.cpp:285] Authenticating with master master@127.0.1.1:59864
> I0620 22:12:29.374776 15794 authenticatee.hpp:128] Creating new client SASL connection
> I0620 22:12:29.374933 15794 master.cpp:817] Dropping 'mesos.internal.AuthenticateMessage' message since not recovered yet
> I0620 22:12:29.375727 15790 detector.cpp:382] A new leading master (UPID=master@127.0.1.1:59864) is detected
> I0620 22:12:29.375789 15790 slave.cpp:581] New master detected at master@127.0.1.1:59864
> I0620 22:12:29.375810 15790 slave.cpp:657] Authenticating with master master@127.0.1.1:59864
> I0620 22:12:29.375845 15790 slave.cpp:630] Detecting new master
> I0620 22:12:29.375882 15790 status_update_manager.cpp:167] New master detected at master@127.0.1.1:59864
> W0620 22:12:29.375896 15790 status_update_manager.cpp:181] Resending status update TASK_RUNNING (UUID: 132905cf-168a-48a5-9ad5-5381463e2e6e) for task 0 of framework 20140620-221229-16842879-59864-15771-0000
> I0620 22:12:29.375908 15790 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: 132905cf-168a-48a5-9ad5-5381463e2e6e) for task 0 of framework 20140620-221229-16842879-59864-15771-0000 to master@127.0.1.1:59864
> I0620 22:12:29.375970 15790 authenticatee.hpp:128] Creating new client SASL connection
> I0620 22:12:29.376078 15790 master.cpp:817] Dropping 'mesos.internal.StatusUpdateMessage' message since not recovered yet
> I0620 22:12:29.376097 15790 master.cpp:817] Dropping 'mesos.internal.AuthenticateMessage' message since not recovered yet
> I0620 22:12:29.379063 15791 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 5.809509ms
> I0620 22:12:29.379096 15791 replica.cpp:342] Persisted promised to 2
> I0620 22:12:29.379273 15791 coordinator.cpp:230] Coordinator attemping to fill missing position
> I0620 22:12:29.379658 15791 replica.cpp:375] Replica received explicit promise request for position 4 with proposal 3
> I0620 22:12:29.379705 15791 leveldb.cpp:438] Reading position from leveldb took 29411ns
> I0620 22:12:29.384661 15791 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 4.936565ms
> I0620 22:12:29.384819 15791 replica.cpp:676] Persisted action at 4
> I0620 22:12:29.385390 15791 replica.cpp:508] Replica received write request for position 4
> I0620 22:12:29.385659 15791 leveldb.cpp:438] Reading position from leveldb took 15704ns
> I0620 22:12:29.390548 15791 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 4.680333ms
> I0620 22:12:29.391034 15791 replica.cpp:676] Persisted action at 4
> I0620 22:12:29.391342 15791 replica.cpp:655] Replica received learned notice for position 4
> I0620 22:12:29.396769 15791 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 5.390672ms
> I0620 22:12:29.397305 15791 leveldb.cpp:401] Deleting ~2 keys from leveldb took 33015ns
> I0620 22:12:29.397632 15791 replica.cpp:676] Persisted action at 4
> I0620 22:12:29.398012 15791 replica.cpp:661] Replica learned TRUNCATE action at position 4
> I0620 22:12:29.401564 15796 log.cpp:672] Writer started with ending position 4
> I0620 22:12:29.401896 15796 leveldb.cpp:438] Reading position from leveldb took 30936ns
> I0620 22:12:29.401921 15796 leveldb.cpp:438] Reading position from leveldb took 5786ns
> I0620 22:12:29.402222 15796 registrar.cpp:346] Successfully fetched the registry (256B)
> I0620 22:12:29.402256 15796 registrar.cpp:422] Attempting to update the 'registry'
> I0620 22:12:29.403610 15796 log.cpp:680] Attempting to append 295 bytes to the log
> I0620 22:12:29.403653 15796 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 5
> I0620 22:12:29.403854 15796 replica.cpp:508] Replica received write request for position 5
> I0620 22:12:29.408926 15796 leveldb.cpp:343] Persisting action (314 bytes) to leveldb took 5.050337ms
> I0620 22:12:29.409181 15796 replica.cpp:676] Persisted action at 5
> I0620 22:12:29.413992 15790 replica.cpp:655] Replica received learned notice for position 5
> I0620 22:12:29.419201 15790 leveldb.cpp:343] Persisting action (316 bytes) to leveldb took 5.1782ms
> I0620 22:12:29.419237 15790 replica.cpp:676] Persisted action at 5
> I0620 22:12:29.419247 15790 replica.cpp:661] Replica learned APPEND action at position 5
> I0620 22:12:29.419589 15790 registrar.cpp:479] Successfully updated 'registry'
> I0620 22:12:29.419643 15790 registrar.cpp:372] Successfully recovered registrar
> I0620 22:12:29.419711 15790 log.cpp:699] Attempting to truncate the log to 5
> I0620 22:12:29.419816 15790 master.cpp:935] Recovered 1 slaves from the Registry (256B) ; allowing 10mins for slaves to re-register
> I0620 22:12:29.419860 15790 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 6
> I0620 22:12:29.420567 15792 replica.cpp:508] Replica received write request for position 6
> I0620 22:12:29.425196 15792 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 4.605186ms
> I0620 22:12:29.425227 15792 replica.cpp:676] Persisted action at 6
> I0620 22:12:29.425431 15792 replica.cpp:655] Replica received learned notice for position 6
> I0620 22:12:29.430459 15792 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 5.007608ms
> I0620 22:12:29.430516 15792 leveldb.cpp:401] Deleting ~2 keys from leveldb took 28852ns
> I0620 22:12:29.430528 15792 replica.cpp:676] Persisted action at 6
> I0620 22:12:29.430537 15792 replica.cpp:661] Replica learned TRUNCATE action at position 6
> I0620 22:12:30.315253 15792 hierarchical_allocator_process.hpp:724] No resources available to allocate!
> I0620 22:12:30.315289 15792 hierarchical_allocator_process.hpp:686] Performed allocation for 0 slaves in 51725ns
> I0620 22:12:31.315965 15792 hierarchical_allocator_process.hpp:724] No resources available to allocate!
> I0620 22:12:31.316007 15792 hierarchical_allocator_process.hpp:686] Performed allocation for 0 slaves in 49055ns
> I0620 22:12:32.316705 15792 hierarchical_allocator_process.hpp:724] No resources available to allocate!
> I0620 22:12:32.317195 15792 hierarchical_allocator_process.hpp:686] Performed allocation for 0 slaves in 493999ns
> I0620 22:12:33.318656 15793 hierarchical_allocator_process.hpp:724] No resources available to allocate!
> I0620 22:12:33.318692 15793 hierarchical_allocator_process.hpp:686] Performed allocation for 0 slaves in 83759ns
> I0620 22:12:34.315120 15791 master.cpp:120] No whitelist given. Advertising offers for all slaves
> I0620 22:12:34.319368 15791 hierarchical_allocator_process.hpp:724] No resources available to allocate!
> I0620 22:12:34.319385 15791 hierarchical_allocator_process.hpp:686] Performed allocation for 0 slaves in 18776ns
> W0620 22:12:34.375746 15791 sched.cpp:380] Authentication timed out
> I0620 22:12:34.375829 15791 sched.cpp:340] Failed to authenticate with master master@127.0.1.1:59864: Authentication discarded
> I0620 22:12:34.375870 15791 sched.cpp:285] Authenticating with master master@127.0.1.1:59864
> I0620 22:12:34.375943 15791 authenticatee.hpp:128] Creating new client SASL connection
> I0620 22:12:34.376127 15791 master.cpp:3457] Authenticating scheduler-3d720a51-c2cb-4670-a37e-1fe811c53a07@127.0.1.1:59864
> I0620 22:12:34.376214 15791 authenticator.hpp:156] Creating new server SASL connection
> I0620 22:12:34.376317 15791 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
> I0620 22:12:34.376335 15791 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0620 22:12:34.376358 15791 authenticator.hpp:262] Received SASL authentication start
> I0620 22:12:34.376406 15791 authenticator.hpp:384] Authentication requires more steps
> I0620 22:12:34.376431 15791 authenticatee.hpp:265] Received SASL authentication step
> I0620 22:12:34.376463 15791 authenticator.hpp:290] Received SASL authentication step
> I0620 22:12:34.376477 15791 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'precise' server FQDN: 'precise' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0620 22:12:34.376484 15791 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
> I0620 22:12:34.376494 15791 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0620 22:12:34.376502 15791 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'precise' server FQDN: 'precise' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0620 22:12:34.376508 15791 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0620 22:12:34.376513 15791 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0620 22:12:34.376523 15791 authenticator.hpp:376] Authentication success
> I0620 22:12:34.376548 15791 authenticatee.hpp:305] Authentication success
> I0620 22:12:34.376569 15791 master.cpp:3497] Successfully authenticated principal 'test-principal' at scheduler-3d720a51-c2cb-4670-a37e-1fe811c53a07@127.0.1.1:59864
> I0620 22:12:34.376631 15791 sched.cpp:359] Successfully authenticated with master master@127.0.1.1:59864
> I0620 22:12:34.376644 15791 sched.cpp:478] Sending registration request to master@127.0.1.1:59864
> I0620 22:12:34.376694 15791 master.cpp:1304] Received re-registration request from framework 20140620-221229-16842879-59864-15771-0000 at scheduler-3d720a51-c2cb-4670-a37e-1fe811c53a07@127.0.1.1:59864
> I0620 22:12:34.376714 15791 master.cpp:1156] Authorizing framework principal 'test-principal' to receive offers for role '*'
> I0620 22:12:34.376831 15791 master.cpp:1355] Re-registering framework 20140620-221229-16842879-59864-15771-0000 at scheduler-3d720a51-c2cb-4670-a37e-1fe811c53a07@127.0.1.1:59864
> I0620 22:12:34.376931 15791 sched.cpp:409] Framework registered with 20140620-221229-16842879-59864-15771-0000
> I0620 22:12:34.376953 15791 sched.cpp:423] Scheduler::registered took 8487ns
> I0620 22:12:34.377058 15791 hierarchical_allocator_process.hpp:331] Added framework 20140620-221229-16842879-59864-15771-0000
> I0620 22:12:34.377068 15791 hierarchical_allocator_process.hpp:724] No resources available to allocate!
> I0620 22:12:34.377074 15791 hierarchical_allocator_process.hpp:686] Performed allocation for 0 slaves in 5932ns
> W0620 22:12:34.377575 15793 slave.cpp:731] Authentication timed out
> W0620 22:12:34.377624 15793 slave.cpp:695] Failed to authenticate with master master@127.0.1.1:59864: Authentication discarded
> I0620 22:12:34.377641 15793 slave.cpp:657] Authenticating with master master@127.0.1.1:59864
> I0620 22:12:34.377686 15793 authenticatee.hpp:128] Creating new client SASL connection
> I0620 22:12:34.377854 15793 master.cpp:3457] Authenticating slave(29)@127.0.1.1:59864
> I0620 22:12:34.377923 15793 authenticator.hpp:156] Creating new server SASL connection
> I0620 22:12:34.378015 15793 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
> I0620 22:12:34.378031 15793 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0620 22:12:34.378047 15793 authenticator.hpp:262] Received SASL authentication start
> I0620 22:12:34.378077 15793 authenticator.hpp:384] Authentication requires more steps
> I0620 22:12:34.378094 15793 authenticatee.hpp:265] Received SASL authentication step
> I0620 22:12:34.378115 15793 authenticator.hpp:290] Received SASL authentication step
> I0620 22:12:34.378128 15793 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'precise' server FQDN: 'precise' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0620 22:12:34.378134 15793 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
> I0620 22:12:34.378141 15793 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0620 22:12:34.378149 15793 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'precise' server FQDN: 'precise' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0620 22:12:34.378154 15793 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0620 22:12:34.378159 15793 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0620 22:12:34.378168 15793 authenticator.hpp:376] Authentication success
> I0620 22:12:34.378183 15793 authenticatee.hpp:305] Authentication success
> I0620 22:12:34.378196 15793 master.cpp:3497] Successfully authenticated principal 'test-principal' at slave(29)@127.0.1.1:59864
> I0620 22:12:34.378340 15795 slave.cpp:714] Successfully authenticated with master master@127.0.1.1:59864
> I0620 22:12:34.378454 15795 slave.cpp:952] Will retry registration in 2.31379ms if necessary
> I0620 22:12:34.378617 15793 master.cpp:2911] Re-registering slave 20140620-221229-16842879-59864-15771-0 at slave(29)@127.0.1.1:59864 (precise)
> I0620 22:12:34.378770 15793 registrar.cpp:422] Attempting to update the 'registry'
> I0620 22:12:34.380069 15793 log.cpp:680] Attempting to append 295 bytes to the log
> I0620 22:12:34.380113 15793 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 7
> I0620 22:12:34.380283 15793 replica.cpp:508] Replica received write request for position 7
> I0620 22:12:34.382016 15797 slave.cpp:952] Will retry registration in 17.58087ms if necessary
> I0620 22:12:34.382084 15797 master.cpp:2904] Ignoring re-register slave message from slave 20140620-221229-16842879-59864-15771-0 at slave(29)@127.0.1.1:59864 (precise) as readmission is already in progress
> I0620 22:12:34.386593 15793 leveldb.cpp:343] Persisting action (314 bytes) to leveldb took 6.289188ms
> I0620 22:12:34.386939 15793 replica.cpp:676] Persisted action at 7
> I0620 22:12:34.393925 15790 replica.cpp:655] Replica received learned notice for position 7
> I0620 22:12:34.399257 15790 leveldb.cpp:343] Persisting action (316 bytes) to leveldb took 5.306209ms
> I0620 22:12:34.399286 15790 replica.cpp:676] Persisted action at 7
> I0620 22:12:34.399296 15790 replica.cpp:661] Replica learned APPEND action at position 7
> I0620 22:12:34.399574 15790 registrar.cpp:479] Successfully updated 'registry'
> I0620 22:12:34.399675 15790 log.cpp:699] Attempting to truncate the log to 7
> I0620 22:12:34.399732 15790 master.cpp:2962] Re-registered slave 20140620-221229-16842879-59864-15771-0 at slave(29)@127.0.1.1:59864 (precise)
> I0620 22:12:34.399762 15790 master.cpp:3923] Adding slave 20140620-221229-16842879-59864-15771-0 at slave(29)@127.0.1.1:59864 (precise) with cpus(*):2; mem(*):1024; disk(*):25116; ports(*):[31000-32000]
> I0620 22:12:34.399864 15790 master.hpp:761] Adding task 0 with resources cpus(*):1; mem(*):500 on slave 20140620-221229-16842879-59864-15771-0 (precise)
> I0620 22:12:34.399976 15790 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 8
> I0620 22:12:34.400038 15790 slave.cpp:798] Re-registered with master master@127.0.1.1:59864
> I0620 22:12:34.400080 15790 slave.cpp:1564] Updating framework 20140620-221229-16842879-59864-15771-0000 pid to scheduler-3d720a51-c2cb-4670-a37e-1fe811c53a07@127.0.1.1:59864
> W0620 22:12:34.400223 15790 status_update_manager.cpp:181] Resending status update TASK_RUNNING (UUID: 132905cf-168a-48a5-9ad5-5381463e2e6e) for task 0 of framework 20140620-221229-16842879-59864-15771-0000
> I0620 22:12:34.400243 15790 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: 132905cf-168a-48a5-9ad5-5381463e2e6e) for task 0 of framework 20140620-221229-16842879-59864-15771-0000 to master@127.0.1.1:59864
> I0620 22:12:34.400337 15790 hierarchical_allocator_process.hpp:444] Added slave 20140620-221229-16842879-59864-15771-0 (precise) with cpus(*):2; mem(*):1024; disk(*):25116; ports(*):[31000-32000] (and cpus(*):1; mem(*):524; disk(*):25116; ports(*):[31000-32000] available)
> I0620 22:12:34.400392 15790 hierarchical_allocator_process.hpp:750] Offering cpus(*):1; mem(*):524; disk(*):25116; ports(*):[31000-32000] on slave 20140620-221229-16842879-59864-15771-0 to framework 20140620-221229-16842879-59864-15771-0000
> I0620 22:12:34.400475 15790 hierarchical_allocator_process.hpp:706] Performed allocation for slave 20140620-221229-16842879-59864-15771-0 in 106278ns
> I0620 22:12:34.400557 15790 master.cpp:3062] Status update TASK_RUNNING (UUID: 132905cf-168a-48a5-9ad5-5381463e2e6e) for task 0 of framework 20140620-221229-16842879-59864-15771-0000 from slave 20140620-221229-16842879-59864-15771-0 at slave(29)@127.0.1.1:59864 (precise)
> I0620 22:12:34.400612 15790 master.hpp:789] Adding offer 20140620-221229-16842879-59864-15771-0 with resources cpus(*):1; mem(*):524; disk(*):25116; ports(*):[31000-32000] on slave 20140620-221229-16842879-59864-15771-0 (precise)
> I0620 22:12:34.400650 15790 master.cpp:3404] Sending 1 offers to framework 20140620-221229-16842879-59864-15771-0000
> tests/allocator_zookeeper_tests.cpp:105: Failure
> Mock function called more times than expected - returning directly.
> Function call: statusUpdate(0x7fff498ab9c0, @0x2b2864099960 80-byte object <10-3D 7A-44 28-2B 00-00 00-00 00-00 00-00 00-00 D0-74 09-64 28-2B 00-00 38-E1 EC-00 00-00 00-00 38-E1 EC-00 00-00 00-00 50-89 06-64 28-2B 00-00 01-00 00-00 00-2B 00-00 00-00 00-00 00-00 00-00 B8-B1 4F-3C 45-E9 D4-41 00-00 00-00 53-00 00-00>)
> Expected: to be called once
> Actual: called twice - over-saturated and active
> I0620 22:12:34.400858 15790 sched.cpp:637] Scheduler::statusUpdate took 134984ns
> I0620 22:12:34.400949 15790 sched.cpp:546] Scheduler::resourceOffers took 18763ns
> I0620 22:12:34.401028 15790 master.cpp:2586] Forwarding status update acknowledgement 132905cf-168a-48a5-9ad5-5381463e2e6e for task 0 of framework 20140620-221229-16842879-59864-15771-0000 to slave 20140620-221229-16842879-59864-15771-0 at slave(29)@127.0.1.1:59864 (precise)
> I0620 22:12:34.401201 15796 replica.cpp:508] Replica received write request for position 8
> I0620 22:12:34.401298 15792 status_update_manager.cpp:398] Received status update acknowledgement (UUID: 132905cf-168a-48a5-9ad5-5381463e2e6e) for task 0 of framework 20140620-221229-16842879-59864-15771-0000
> I0620 22:12:34.401882 15792 slave.cpp:1654] Status update manager successfully handled status update acknowledgement (UUID: 132905cf-168a-48a5-9ad5-5381463e2e6e) for task 0 of framework 20140620-221229-16842879-59864-15771-0000
> I0620 22:12:34.402114 15771 master.cpp:610] Master terminating
> I0620 22:12:34.402158 15771 master.hpp:779] Removing task 0 with resources cpus(*):1; mem(*):500 on slave 20140620-221229-16842879-59864-15771-0 (precise)
> W0620 22:12:34.402195 15771 master.cpp:4209] Removing task 0 of framework 20140620-221229-16842879-59864-15771-0000 and slave 20140620-221229-16842879-59864-15771-0 in non-terminal state TASK_RUNNING
> I0620 22:12:34.402242 15771 master.hpp:799] Removing offer 20140620-221229-16842879-59864-15771-0 with resources cpus(*):1; mem(*):524; disk(*):25116; ports(*):[31000-32000] on slave 20140620-221229-16842879-59864-15771-0 (precise)
> I0620 22:12:34.402901 15791 sched.cpp:747] Stopping framework '20140620-221229-16842879-59864-15771-0000'
> I0620 22:12:34.403477 15792 slave.cpp:2311] master@127.0.1.1:59864 exited
> W0620 22:12:34.403494 15792 slave.cpp:2314] Master disconnected! Waiting for a new master to be elected
> 2014-06-20 22:12:34,403:15771(0x2b2846641f80):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x146bcd70e300008 to [127.0.0.1:42843]
> 2014-06-20 22:12:34,405:15771(0x2b2846641f80):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x146bcd70e300009 to [127.0.0.1:42843]
> I0620 22:12:34.406445 15796 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 5.218772ms
> I0620 22:12:34.406472 15796 replica.cpp:676] Persisted action at 8
> I0620 22:12:34.409512 15771 contender.cpp:186] Now cancelling the membership: 2
> I0620 22:12:34.409955 15792 group.cpp:619] Trying to remove '/znode/info_0000000002' in ZooKeeper
> 2014-06-20 22:12:34,414:15771(0x2b2846a48700):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x146bcd70e300007 to [127.0.0.1:42843]
> I0620 22:12:34.420526 15793 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
> I0620 22:12:34.420570 15793 detector.cpp:126] The current leader (id=2) is lost
> I0620 22:12:34.420579 15793 detector.cpp:138] Detected a new leader: None
> I0620 22:12:34.420655 15793 slave.cpp:626] Lost leading master
> I0620 22:12:34.420665 15793 slave.cpp:630] Detecting new master
> I0620 22:12:34.420735 15794 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
> I0620 22:12:34.420766 15794 detector.cpp:126] The current leader (id=2) is lost
> I0620 22:12:34.420774 15794 detector.cpp:138] Detected a new leader: None
> I0620 22:12:34.420862 15796 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
> I0620 22:12:34.420893 15796 detector.cpp:126] The current leader (id=2) is lost
> I0620 22:12:34.420902 15796 detector.cpp:138] Detected a new leader: None
> 2014-06-20 22:12:34,426:15771(0x2b2846641f80):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x146bcd70e300006 to [127.0.0.1:42843]
> I0620 22:12:34.426604 15771 slave.cpp:466] Slave terminating
> I0620 22:12:34.426631 15771 slave.cpp:1387] Asked to shut down framework 20140620-221229-16842879-59864-15771-0000 by @0.0.0.0:0
> W0620 22:12:34.426641 15771 slave.cpp:1395] Ignoring shutdown framework message for 20140620-221229-16842879-59864-15771-0000 because the slave has not yet registered with the master
> 2014-06-20 22:12:34,427:15771(0x2b2846641f80):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x146bcd70e300005 to [127.0.0.1:42843]
> 2014-06-20 22:12:34,427:15771(0x2b2846641f80):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x146bcd70e300004 to [127.0.0.1:42843]
> [ FAILED ] AllocatorZooKeeperTest/0.FrameworkReregistersFirst, where TypeParam = mesos::internal::master::allocator::HierarchicalAllocatorProcess<mesos::internal::master::allocator::DRFSorter, mesos::internal::master::allocator::DRFSorter> (5456 ms)
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.2#6252)