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/25 02:15:25 UTC
[jira] [Created] (MESOS-1536)
AllocatorZooKeeperTest/0.FrameworkReregistersFirst
Vinod Kone created MESOS-1536:
---------------------------------
Summary: AllocatorZooKeeperTest/0.FrameworkReregistersFirst
Key: MESOS-1536
URL: https://issues.apache.org/jira/browse/MESOS-1536
Project: Mesos
Issue Type: Bug
Components: test
Reporter: Vinod Kone
{code}
[ RUN ] AllocatorZooKeeperTest/0.FrameworkReregistersFirst
Using temporary directory '/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_bhNlHH'
I0624 14:16:28.486592 3799 leveldb.cpp:176] Opened db in 4.724895ms
I0624 14:16:28.488145 3799 leveldb.cpp:183] Compacted db in 1.104384ms
I0624 14:16:28.488579 3799 leveldb.cpp:198] Created db iterator in 25956ns
I0624 14:16:28.488826 3799 leveldb.cpp:204] Seeked to beginning of db in 13801ns
I0624 14:16:28.489085 3799 leveldb.cpp:273] Iterated through 0 keys in the db in 13299ns
I0624 14:16:28.489382 3799 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
2014-06-24 14:16:28,489:3799(0x2ba5c2dd1700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
2014-06-24 14:16:28,489:3799(0x2ba5c2dd1700):ZOO_INFO@log_env@716: Client environment:host.name=saucy
2014-06-24 14:16:28,489:3799(0x2ba5c2dd1700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
2014-06-24 14:16:28,489:3799(0x2ba5c2dd1700):ZOO_INFO@log_env@724: Client environment:os.arch=3.11.0-23-generic
2014-06-24 14:16:28,489:3799(0x2ba5c2dd1700):ZOO_INFO@log_env@725: Client environment:os.version=#40-Ubuntu SMP Wed Jun 4 21:05:23 UTC 2014
2014-06-24 14:16:28,490:3799(0x2ba5c2dd1700):ZOO_INFO@log_env@733: Client environment:user.name=jenkins
2014-06-24 14:16:28,490:3799(0x2ba5c2dd1700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
2014-06-24 14:16:28,490:3799(0x2ba5c2dd1700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_bhNlHH
2014-06-24 14:16:28,490:3799(0x2ba5c2dd1700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:36775 sessionTimeout=10000 watcher=0x2ba5bb82b610 sessionId=0 sessionPasswd=<null> context=0x2ba5e41130a0 flags=0
2014-06-24 14:16:28,490:3799(0x2ba5c31d3700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
2014-06-24 14:16:28,490:3799(0x2ba5c31d3700):ZOO_INFO@log_env@716: Client environment:host.name=saucy
2014-06-24 14:16:28,490:3799(0x2ba5c31d3700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
2014-06-24 14:16:28,490:3799(0x2ba5c31d3700):ZOO_INFO@log_env@724: Client environment:os.arch=3.11.0-23-generic
2014-06-24 14:16:28,490:3799(0x2ba5c31d3700):ZOO_INFO@log_env@725: Client environment:os.version=#40-Ubuntu SMP Wed Jun 4 21:05:23 UTC 2014
2014-06-24 14:16:28,490:3799(0x2ba5c31d3700):ZOO_INFO@log_env@733: Client environment:user.name=jenkins
2014-06-24 14:16:28,490:3799(0x2ba5c31d3700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
2014-06-24 14:16:28,490:3799(0x2ba5c31d3700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_bhNlHH
2014-06-24 14:16:28,490:3799(0x2ba5c31d3700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:36775 sessionTimeout=10000 watcher=0x2ba5bb82b610 sessionId=0 sessionPasswd=<null> context=0x2ba5c807c830 flags=0
I0624 14:16:28.491173 3817 log.cpp:238] Attempting to join replica to ZooKeeper group
I0624 14:16:28.491346 3817 recover.cpp:425] Starting replica recovery
I0624 14:16:28.491436 3817 recover.cpp:451] Replica is in EMPTY status
I0624 14:16:28.491834 3819 replica.cpp:638] Replica in EMPTY status received a broadcasted recover request
I0624 14:16:28.492003 3817 recover.cpp:188] Received a recover response from a replica in EMPTY status
I0624 14:16:28.492089 3817 recover.cpp:542] Updating replica status to STARTING
I0624 14:16:28.493083 3817 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 943330ns
I0624 14:16:28.493103 3817 replica.cpp:320] Persisted replica status to STARTING
I0624 14:16:28.493158 3817 recover.cpp:451] Replica is in STARTING status
I0624 14:16:28.493394 3817 replica.cpp:638] Replica in STARTING status received a broadcasted recover request
I0624 14:16:28.493443 3817 recover.cpp:188] Received a recover response from a replica in STARTING status
I0624 14:16:28.493515 3817 recover.cpp:542] Updating replica status to VOTING
I0624 14:16:28.493860 3817 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 310602ns
I0624 14:16:28.493880 3817 replica.cpp:320] Persisted replica status to VOTING
I0624 14:16:28.493940 3824 recover.cpp:556] Successfully joined the Paxos group
I0624 14:16:28.494000 3818 recover.cpp:440] Recover process terminated
2014-06-24 14:16:28,495:3799(0x2ba5c2bd0700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
2014-06-24 14:16:28,495:3799(0x2ba5c2bd0700):ZOO_INFO@log_env@716: Client environment:host.name=saucy
2014-06-24 14:16:28,495:3799(0x2ba5c2bd0700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
2014-06-24 14:16:28,495:3799(0x2ba5c2bd0700):ZOO_INFO@log_env@724: Client environment:os.arch=3.11.0-23-generic
2014-06-24 14:16:28,495:3799(0x2ba5c2bd0700):ZOO_INFO@log_env@725: Client environment:os.version=#40-Ubuntu SMP Wed Jun 4 21:05:23 UTC 2014
2014-06-24 14:16:28,495:3799(0x2ba5c2bd0700):ZOO_INFO@log_env@733: Client environment:user.name=jenkins
2014-06-24 14:16:28,495:3799(0x2ba5c2bd0700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
2014-06-24 14:16:28,495:3799(0x2ba5c2bd0700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_bhNlHH
2014-06-24 14:16:28,495:3799(0x2ba5c2bd0700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:36775 sessionTimeout=10000 watcher=0x2ba5bb82b610 sessionId=0 sessionPasswd=<null> context=0x2ba5d40692b0 flags=0
2014-06-24 14:16:28,496:3799(0x2ba5c2fd2700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
2014-06-24 14:16:28,496:3799(0x2ba5c2fd2700):ZOO_INFO@log_env@716: Client environment:host.name=saucy
2014-06-24 14:16:28,496:3799(0x2ba5c2fd2700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
2014-06-24 14:16:28,496:3799(0x2ba5c2fd2700):ZOO_INFO@log_env@724: Client environment:os.arch=3.11.0-23-generic
2014-06-24 14:16:28,496:3799(0x2ba5c2fd2700):ZOO_INFO@log_env@725: Client environment:os.version=#40-Ubuntu SMP Wed Jun 4 21:05:23 UTC 2014
2014-06-24 14:16:28,496:3799(0x2ba5c2fd2700):ZOO_INFO@log_env@733: Client environment:user.name=jenkins
2014-06-24 14:16:28,496:3799(0x2ba5c2fd2700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
2014-06-24 14:16:28,496:3799(0x2ba5c2fd2700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_bhNlHH
2014-06-24 14:16:28,496:3799(0x2ba5c2fd2700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:36775 sessionTimeout=10000 watcher=0x2ba5bb82b610 sessionId=0 sessionPasswd=<null> context=0x2ba5cc0f6710 flags=0
I0624 14:16:28.498399 3817 master.cpp:288] Master 20140624-141628-16842879-47356-3799 (saucy) started on 127.0.1.1:47356
I0624 14:16:28.498525 3817 master.cpp:325] Master only allowing authenticated frameworks to register
I0624 14:16:28.498536 3817 master.cpp:330] Master only allowing authenticated slaves to register
I0624 14:16:28.498548 3817 credentials.hpp:35] Loading credentials for authentication from '/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_bhNlHH/credentials'
I0624 14:16:28.499171 3817 master.cpp:356] Authorization enabled
I0624 14:16:28.499922 3818 master.cpp:122] No whitelist given. Advertising offers for all slaves
I0624 14:16:28.500176 3818 contender.cpp:131] Joining the ZK group
I0624 14:16:28.500377 3817 hierarchical_allocator_process.hpp:301] Initializing hierarchical allocator process with master : master@127.0.1.1:47356
2014-06-24 14:16:28,502:3799(0x2ba5edd57700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:36775]
2014-06-24 14:16:28,509:3799(0x2ba5edd57700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:36775], sessionId=0x146cfbcb1c00000, negotiated timeout=10000
2014-06-24 14:16:28,508:3799(0x2ba5ed151700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:36775]
2014-06-24 14:16:28,513:3799(0x2ba5ed151700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:36775], sessionId=0x146cfbcb1c00002, negotiated timeout=10000
2014-06-24 14:16:28,505:3799(0x2ba5ecd3f700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:36775]
2014-06-24 14:16:28,513:3799(0x2ba5ecd3f700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:36775], sessionId=0x146cfbcb1c00001, negotiated timeout=10000
2014-06-24 14:16:28,509:3799(0x2ba5ed553700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:36775]
2014-06-24 14:16:28,513:3799(0x2ba5ed553700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:36775], sessionId=0x146cfbcb1c00003, negotiated timeout=10000
I0624 14:16:28.527004 3821 group.cpp:313] Group process (group(57)@127.0.1.1:47356) connected to ZooKeeper
I0624 14:16:28.527040 3821 group.cpp:787] Syncing group operations: queue size (joins, cancels, datas) = (0, 0, 0)
I0624 14:16:28.527048 3821 group.cpp:385] Trying to create path '/znode/log_replicas' in ZooKeeper
I0624 14:16:28.528270 3823 group.cpp:313] Group process (group(58)@127.0.1.1:47356) connected to ZooKeeper
I0624 14:16:28.528290 3823 group.cpp:787] Syncing group operations: queue size (joins, cancels, datas) = (1, 0, 0)
I0624 14:16:28.528297 3823 group.cpp:385] Trying to create path '/znode/log_replicas' in ZooKeeper
I0624 14:16:28.533304 3822 group.cpp:313] Group process (group(60)@127.0.1.1:47356) connected to ZooKeeper
I0624 14:16:28.533331 3822 group.cpp:787] Syncing group operations: queue size (joins, cancels, datas) = (0, 0, 0)
I0624 14:16:28.533339 3822 group.cpp:385] Trying to create path '/znode' in ZooKeeper
I0624 14:16:28.534025 3819 group.cpp:313] Group process (group(59)@127.0.1.1:47356) connected to ZooKeeper
I0624 14:16:28.534046 3819 group.cpp:787] Syncing group operations: queue size (joins, cancels, datas) = (1, 0, 0)
I0624 14:16:28.534054 3819 group.cpp:385] Trying to create path '/znode' in ZooKeeper
I0624 14:16:28.540894 3822 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
I0624 14:16:28.542295 3822 contender.cpp:247] New candidate (id='1') has entered the contest for leadership
I0624 14:16:28.545615 3824 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
I0624 14:16:28.545678 3824 detector.cpp:138] Detected a new leader: (id='1')
I0624 14:16:28.545794 3824 group.cpp:658] Trying to get '/znode/info_0000000001' in ZooKeeper
I0624 14:16:28.546679 3819 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
I0624 14:16:28.547430 3822 network.hpp:423] ZooKeeper group memberships changed
I0624 14:16:28.547551 3822 group.cpp:658] Trying to get '/znode/log_replicas/0000000000' in ZooKeeper
I0624 14:16:28.549092 3824 detector.cpp:382] A new leading master (UPID=master@127.0.1.1:47356) is detected
I0624 14:16:28.549182 3824 master.cpp:1122] The newly elected leader is master@127.0.1.1:47356 with id 20140624-141628-16842879-47356-3799
I0624 14:16:28.549206 3824 master.cpp:1135] Elected as the leading master!
I0624 14:16:28.549212 3824 master.cpp:953] Recovering from registrar
I0624 14:16:28.549289 3824 registrar.cpp:313] Recovering registrar
I0624 14:16:28.549643 3824 log.cpp:656] Attempting to start the writer
I0624 14:16:28.550079 3824 replica.cpp:474] Replica received implicit promise request with proposal 1
I0624 14:16:28.551067 3822 network.hpp:461] ZooKeeper group PIDs: { log-replica(374)@127.0.1.1:47356 }
I0624 14:16:28.551326 3824 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 1.325696ms
I0624 14:16:28.551451 3824 replica.cpp:342] Persisted promised to 1
I0624 14:16:28.551671 3824 coordinator.cpp:230] Coordinator attemping to fill missing position
I0624 14:16:28.552048 3824 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2
I0624 14:16:28.553045 3824 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 991215ns
I0624 14:16:28.553395 3824 replica.cpp:676] Persisted action at 0
I0624 14:16:28.559146 3819 replica.cpp:508] Replica received write request for position 0
I0624 14:16:28.559197 3819 leveldb.cpp:438] Reading position from leveldb took 34680ns
I0624 14:16:28.560307 3819 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 1.102171ms
I0624 14:16:28.560338 3819 replica.cpp:676] Persisted action at 0
I0624 14:16:28.560493 3819 replica.cpp:655] Replica received learned notice for position 0
I0624 14:16:28.560897 3819 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 399622ns
I0624 14:16:28.560916 3819 replica.cpp:676] Persisted action at 0
I0624 14:16:28.560925 3819 replica.cpp:661] Replica learned NOP action at position 0
I0624 14:16:28.561095 3819 log.cpp:672] Writer started with ending position 0
I0624 14:16:28.561414 3819 leveldb.cpp:438] Reading position from leveldb took 20268ns
I0624 14:16:28.566865 3823 registrar.cpp:346] Successfully fetched the registry (0B)
I0624 14:16:28.566911 3823 registrar.cpp:422] Attempting to update the 'registry'
I0624 14:16:28.568617 3818 log.cpp:680] Attempting to append 117 bytes to the log
I0624 14:16:28.568672 3818 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1
I0624 14:16:28.568863 3818 replica.cpp:508] Replica received write request for position 1
I0624 14:16:28.569772 3818 leveldb.cpp:343] Persisting action (134 bytes) to leveldb took 901317ns
I0624 14:16:28.569790 3818 replica.cpp:676] Persisted action at 1
I0624 14:16:28.569978 3818 replica.cpp:655] Replica received learned notice for position 1
I0624 14:16:28.570363 3818 leveldb.cpp:343] Persisting action (136 bytes) to leveldb took 379970ns
I0624 14:16:28.570382 3818 replica.cpp:676] Persisted action at 1
I0624 14:16:28.570389 3818 replica.cpp:661] Replica learned APPEND action at position 1
I0624 14:16:28.570659 3818 registrar.cpp:479] Successfully updated 'registry'
I0624 14:16:28.570703 3818 registrar.cpp:372] Successfully recovered registrar
I0624 14:16:28.570791 3824 log.cpp:699] Attempting to truncate the log to 1
I0624 14:16:28.570844 3824 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2
I0624 14:16:28.571005 3824 replica.cpp:508] Replica received write request for position 2
I0624 14:16:28.571454 3818 master.cpp:980] Recovered 0 slaves from the Registry (81B) ; allowing 10mins for slaves to re-register
I0624 14:16:28.572257 3824 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 1.246015ms
I0624 14:16:28.572281 3824 replica.cpp:676] Persisted action at 2
I0624 14:16:28.572427 3824 replica.cpp:655] Replica received learned notice for position 2
I0624 14:16:28.574789 3824 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 2.357624ms
I0624 14:16:28.575325 3818 slave.cpp:168] Slave started on 172)@127.0.1.1:47356
I0624 14:16:28.575685 3818 credentials.hpp:35] Loading credentials for authentication from '/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_YhPs1N/credential'
2014-06-24 14:16:28,575:3799(0x2ba5c33d4700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
2014-06-24 14:16:28,575:3799(0x2ba5c33d4700):ZOO_INFO@log_env@716: Client environment:host.name=saucy
2014-06-24 14:16:28,575:3799(0x2ba5c33d4700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
2014-06-24 14:16:28,576:3799(0x2ba5c33d4700):ZOO_INFO@log_env@724: Client environment:os.arch=3.11.0-23-generic
2014-06-24 14:16:28,576:3799(0x2ba5c33d4700):ZOO_INFO@log_env@725: Client environment:os.version=#40-Ubuntu SMP Wed Jun 4 21:05:23 UTC 2014
I0624 14:16:28.576344 3824 leveldb.cpp:401] Deleting ~1 keys from leveldb took 1.540415ms
I0624 14:16:28.576370 3824 replica.cpp:676] Persisted action at 2
I0624 14:16:28.576377 3824 replica.cpp:661] Replica learned TRUNCATE action at position 2
I0624 14:16:28.576704 3818 slave.cpp:268] Slave using credential for: test-principal
I0624 14:16:28.577131 3818 slave.cpp:281] Slave resources: cpus(*):2; mem(*):1024; disk(*):24988; ports(*):[31000-32000]
I0624 14:16:28.577453 3818 slave.cpp:309] Slave hostname: saucy
I0624 14:16:28.577718 3818 slave.cpp:310] Slave checkpoint: false
2014-06-24 14:16:28,576:3799(0x2ba5c33d4700):ZOO_INFO@log_env@733: Client environment:user.name=jenkins
2014-06-24 14:16:28,578:3799(0x2ba5c33d4700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
2014-06-24 14:16:28,578:3799(0x2ba5c33d4700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_bhNlHH
2014-06-24 14:16:28,578:3799(0x2ba5c33d4700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:36775 sessionTimeout=10000 watcher=0x2ba5bb82b610 sessionId=0 sessionPasswd=<null> context=0x2ba5e00773b0 flags=0
I0624 14:16:28.579043 3818 state.cpp:33] Recovering state from '/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_YhPs1N/meta'
2014-06-24 14:16:28,579:3799(0x2ba5c27ce700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
2014-06-24 14:16:28,579:3799(0x2ba5c27ce700):ZOO_INFO@log_env@716: Client environment:host.name=saucy
2014-06-24 14:16:28,579:3799(0x2ba5c27ce700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
2014-06-24 14:16:28,579:3799(0x2ba5c27ce700):ZOO_INFO@log_env@724: Client environment:os.arch=3.11.0-23-generic
2014-06-24 14:16:28,579:3799(0x2ba5c27ce700):ZOO_INFO@log_env@725: Client environment:os.version=#40-Ubuntu SMP Wed Jun 4 21:05:23 UTC 2014
2014-06-24 14:16:28,579:3799(0x2ba5c27ce700):ZOO_INFO@log_env@733: Client environment:user.name=jenkins
2014-06-24 14:16:28,580:3799(0x2ba5c27ce700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
2014-06-24 14:16:28,580:3799(0x2ba5c27ce700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_bhNlHH
2014-06-24 14:16:28,580:3799(0x2ba5c27ce700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:36775 sessionTimeout=10000 watcher=0x2ba5bb82b610 sessionId=0 sessionPasswd=<null> context=0x2ba5e40f6b60 flags=0
I0624 14:16:28.580518 3822 status_update_manager.cpp:193] Recovering status update manager
I0624 14:16:28.580914 3822 slave.cpp:3111] Finished recovery
I0624 14:16:28.581533 3799 sched.cpp:139] Version: 0.20.0
2014-06-24 14:16:28,583:3799(0x2ba5ee97d700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:36775]
2014-06-24 14:16:28,588:3799(0x2ba5ee97d700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:36775], sessionId=0x146cfbcb1c00004, negotiated timeout=10000
I0624 14:16:28.590548 3822 group.cpp:313] Group process (group(62)@127.0.1.1:47356) connected to ZooKeeper
I0624 14:16:28.590572 3822 group.cpp:787] Syncing group operations: queue size (joins, cancels, datas) = (0, 0, 0)
I0624 14:16:28.590580 3822 group.cpp:385] Trying to create path '/znode' in ZooKeeper
2014-06-24 14:16:28,588:3799(0x2ba5ee77c700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:36775]
2014-06-24 14:16:28,590:3799(0x2ba5ee77c700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:36775], sessionId=0x146cfbcb1c00005, negotiated timeout=10000
I0624 14:16:28.591204 3817 group.cpp:313] Group process (group(61)@127.0.1.1:47356) connected to ZooKeeper
I0624 14:16:28.591224 3817 group.cpp:787] Syncing group operations: queue size (joins, cancels, datas) = (0, 0, 0)
I0624 14:16:28.591230 3817 group.cpp:385] Trying to create path '/znode' in ZooKeeper
I0624 14:16:28.599617 3817 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
I0624 14:16:28.599684 3817 detector.cpp:138] Detected a new leader: (id='1')
I0624 14:16:28.599802 3817 group.cpp:658] Trying to get '/znode/info_0000000001' in ZooKeeper
I0624 14:16:28.602834 3822 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
I0624 14:16:28.602887 3822 detector.cpp:138] Detected a new leader: (id='1')
I0624 14:16:28.602974 3822 group.cpp:658] Trying to get '/znode/info_0000000001' in ZooKeeper
I0624 14:16:28.606925 3817 detector.cpp:382] A new leading master (UPID=master@127.0.1.1:47356) is detected
I0624 14:16:28.607023 3817 slave.cpp:584] New master detected at master@127.0.1.1:47356
I0624 14:16:28.607046 3817 slave.cpp:660] Authenticating with master master@127.0.1.1:47356
I0624 14:16:28.607115 3817 slave.cpp:633] Detecting new master
I0624 14:16:28.607156 3817 status_update_manager.cpp:167] New master detected at master@127.0.1.1:47356
I0624 14:16:28.607204 3817 authenticatee.hpp:128] Creating new client SASL connection
I0624 14:16:28.607452 3817 master.cpp:3499] Authenticating slave(172)@127.0.1.1:47356
I0624 14:16:28.607583 3817 authenticator.hpp:156] Creating new server SASL connection
I0624 14:16:28.607741 3817 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
I0624 14:16:28.607774 3817 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
I0624 14:16:28.607807 3817 authenticator.hpp:262] Received SASL authentication start
I0624 14:16:28.607862 3817 authenticator.hpp:384] Authentication requires more steps
I0624 14:16:28.607889 3817 authenticatee.hpp:265] Received SASL authentication step
I0624 14:16:28.607929 3817 authenticator.hpp:290] Received SASL authentication step
I0624 14:16:28.607951 3817 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
I0624 14:16:28.607967 3817 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I0624 14:16:28.607980 3817 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0624 14:16:28.607993 3817 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
I0624 14:16:28.608000 3817 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0624 14:16:28.608006 3817 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0624 14:16:28.608016 3817 authenticator.hpp:376] Authentication success
I0624 14:16:28.608042 3817 authenticatee.hpp:305] Authentication success
I0624 14:16:28.608067 3817 master.cpp:3539] Successfully authenticated principal 'test-principal' at slave(172)@127.0.1.1:47356
I0624 14:16:28.608151 3817 slave.cpp:717] Successfully authenticated with master master@127.0.1.1:47356
I0624 14:16:28.608203 3817 slave.cpp:955] Will retry registration in 19.062319ms if necessary
I0624 14:16:28.608700 3817 master.cpp:2781] Registering slave at slave(172)@127.0.1.1:47356 (saucy) with id 20140624-141628-16842879-47356-3799-0
I0624 14:16:28.608814 3817 registrar.cpp:422] Attempting to update the 'registry'
I0624 14:16:28.609616 3822 detector.cpp:382] A new leading master (UPID=master@127.0.1.1:47356) is detected
I0624 14:16:28.609690 3822 sched.cpp:235] New master detected at master@127.0.1.1:47356
I0624 14:16:28.609716 3822 sched.cpp:285] Authenticating with master master@127.0.1.1:47356
I0624 14:16:28.609786 3822 authenticatee.hpp:128] Creating new client SASL connection
I0624 14:16:28.609921 3822 master.cpp:3499] Authenticating scheduler-40f24577-8f86-45de-8e3e-7d64238547c1@127.0.1.1:47356
I0624 14:16:28.609995 3822 authenticator.hpp:156] Creating new server SASL connection
I0624 14:16:28.610086 3822 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
I0624 14:16:28.610105 3822 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
I0624 14:16:28.610124 3822 authenticator.hpp:262] Received SASL authentication start
I0624 14:16:28.610158 3822 authenticator.hpp:384] Authentication requires more steps
I0624 14:16:28.610182 3822 authenticatee.hpp:265] Received SASL authentication step
I0624 14:16:28.610208 3822 authenticator.hpp:290] Received SASL authentication step
I0624 14:16:28.610221 3822 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
I0624 14:16:28.610227 3822 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I0624 14:16:28.610236 3822 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0624 14:16:28.610244 3822 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
I0624 14:16:28.610249 3822 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0624 14:16:28.610255 3822 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0624 14:16:28.610265 3822 authenticator.hpp:376] Authentication success
I0624 14:16:28.610285 3822 authenticatee.hpp:305] Authentication success
I0624 14:16:28.610306 3822 master.cpp:3539] Successfully authenticated principal 'test-principal' at scheduler-40f24577-8f86-45de-8e3e-7d64238547c1@127.0.1.1:47356
I0624 14:16:28.610363 3822 sched.cpp:359] Successfully authenticated with master master@127.0.1.1:47356
I0624 14:16:28.610375 3822 sched.cpp:478] Sending registration request to master@127.0.1.1:47356
I0624 14:16:28.610424 3822 master.cpp:1241] Received registration request from scheduler-40f24577-8f86-45de-8e3e-7d64238547c1@127.0.1.1:47356
I0624 14:16:28.610445 3822 master.cpp:1201] Authorizing framework principal 'test-principal' to receive offers for role '*'
I0624 14:16:28.610581 3822 master.cpp:1300] Registering framework 20140624-141628-16842879-47356-3799-0000 at scheduler-40f24577-8f86-45de-8e3e-7d64238547c1@127.0.1.1:47356
I0624 14:16:28.610689 3822 sched.cpp:409] Framework registered with 20140624-141628-16842879-47356-3799-0000
I0624 14:16:28.610712 3822 sched.cpp:423] Scheduler::registered took 12893ns
I0624 14:16:28.610862 3822 hierarchical_allocator_process.hpp:331] Added framework 20140624-141628-16842879-47356-3799-0000
I0624 14:16:28.610880 3822 hierarchical_allocator_process.hpp:724] No resources available to allocate!
I0624 14:16:28.610890 3822 hierarchical_allocator_process.hpp:686] Performed allocation for 0 slaves in 18796ns
I0624 14:16:28.612501 3818 log.cpp:680] Attempting to append 287 bytes to the log
I0624 14:16:28.612560 3818 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3
I0624 14:16:28.612779 3818 replica.cpp:508] Replica received write request for position 3
I0624 14:16:28.613858 3818 leveldb.cpp:343] Persisting action (306 bytes) to leveldb took 1.072646ms
I0624 14:16:28.613888 3818 replica.cpp:676] Persisted action at 3
I0624 14:16:28.614060 3818 replica.cpp:655] Replica received learned notice for position 3
I0624 14:16:28.615028 3818 leveldb.cpp:343] Persisting action (308 bytes) to leveldb took 963724ns
I0624 14:16:28.615051 3818 replica.cpp:676] Persisted action at 3
I0624 14:16:28.615058 3818 replica.cpp:661] Replica learned APPEND action at position 3
I0624 14:16:28.615350 3818 registrar.cpp:479] Successfully updated 'registry'
I0624 14:16:28.615412 3818 log.cpp:699] Attempting to truncate the log to 3
I0624 14:16:28.615463 3818 master.cpp:2821] Registered slave 20140624-141628-16842879-47356-3799-0 at slave(172)@127.0.1.1:47356 (saucy)
I0624 14:16:28.615478 3818 master.cpp:3967] Adding slave 20140624-141628-16842879-47356-3799-0 at slave(172)@127.0.1.1:47356 (saucy) with cpus(*):2; mem(*):1024; disk(*):24988; ports(*):[31000-32000]
I0624 14:16:28.615564 3818 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4
I0624 14:16:28.615634 3818 slave.cpp:751] Registered with master master@127.0.1.1:47356; given slave ID 20140624-141628-16842879-47356-3799-0
I0624 14:16:28.615708 3818 hierarchical_allocator_process.hpp:444] Added slave 20140624-141628-16842879-47356-3799-0 (saucy) with cpus(*):2; mem(*):1024; disk(*):24988; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):24988; ports(*):[31000-32000] available)
I0624 14:16:28.615761 3818 hierarchical_allocator_process.hpp:750] Offering cpus(*):2; mem(*):1024; disk(*):24988; ports(*):[31000-32000] on slave 20140624-141628-16842879-47356-3799-0 to framework 20140624-141628-16842879-47356-3799-0000
I0624 14:16:28.615859 3818 hierarchical_allocator_process.hpp:706] Performed allocation for slave 20140624-141628-16842879-47356-3799-0 in 135412ns
I0624 14:16:28.615912 3818 slave.cpp:2308] Received ping from slave-observer(153)@127.0.1.1:47356
I0624 14:16:28.615972 3818 master.hpp:794] Adding offer 20140624-141628-16842879-47356-3799-0 with resources cpus(*):2; mem(*):1024; disk(*):24988; ports(*):[31000-32000] on slave 20140624-141628-16842879-47356-3799-0 (saucy)
I0624 14:16:28.616021 3818 master.cpp:3446] Sending 1 offers to framework 20140624-141628-16842879-47356-3799-0000
I0624 14:16:28.616278 3818 sched.cpp:546] Scheduler::resourceOffers took 154746ns
I0624 14:16:28.616469 3818 master.hpp:804] Removing offer 20140624-141628-16842879-47356-3799-0 with resources cpus(*):2; mem(*):1024; disk(*):24988; ports(*):[31000-32000] on slave 20140624-141628-16842879-47356-3799-0 (saucy)
I0624 14:16:28.616513 3818 master.cpp:2125] Processing reply for offers: [ 20140624-141628-16842879-47356-3799-0 ] on slave 20140624-141628-16842879-47356-3799-0 at slave(172)@127.0.1.1:47356 (saucy) for framework 20140624-141628-16842879-47356-3799-0000
I0624 14:16:28.616559 3818 master.cpp:2211] Authorizing framework principal 'test-principal' to launch task 0 as user 'jenkins'
I0624 14:16:28.616895 3818 master.hpp:766] Adding task 0 with resources cpus(*):1; mem(*):500 on slave 20140624-141628-16842879-47356-3799-0 (saucy)
I0624 14:16:28.616929 3818 master.cpp:2277] Launching task 0 of framework 20140624-141628-16842879-47356-3799-0000 with resources cpus(*):1; mem(*):500 on slave 20140624-141628-16842879-47356-3799-0 at slave(172)@127.0.1.1:47356 (saucy)
I0624 14:16:28.617506 3822 slave.cpp:986] Got assigned task 0 for framework 20140624-141628-16842879-47356-3799-0000
I0624 14:16:28.617718 3822 slave.cpp:1096] Launching task 0 for framework 20140624-141628-16842879-47356-3799-0000
I0624 14:16:28.618793 3821 hierarchical_allocator_process.hpp:546] Framework 20140624-141628-16842879-47356-3799-0000 left cpus(*):1; mem(*):524; disk(*):24988; ports(*):[31000-32000] unused on slave 20140624-141628-16842879-47356-3799-0
I0624 14:16:28.618891 3821 hierarchical_allocator_process.hpp:588] Framework 20140624-141628-16842879-47356-3799-0000 filtered slave 20140624-141628-16842879-47356-3799-0 for 5secs
I0624 14:16:28.621037 3822 exec.cpp:131] Version: 0.20.0
I0624 14:16:28.621412 3818 replica.cpp:508] Replica received write request for position 4
I0624 14:16:28.621951 3819 exec.cpp:181] Executor started at: executor(56)@127.0.1.1:47356 with pid 3799
I0624 14:16:28.622318 3822 slave.cpp:1206] Queuing task '0' for executor default of framework '20140624-141628-16842879-47356-3799-0000
I0624 14:16:28.622678 3818 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 895455ns
I0624 14:16:28.622997 3818 replica.cpp:676] Persisted action at 4
I0624 14:16:28.626545 3822 slave.cpp:545] Successfully attached file '/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_YhPs1N/slaves/20140624-141628-16842879-47356-3799-0/frameworks/20140624-141628-16842879-47356-3799-0000/executors/default/runs/3e46be2b-35b9-4893-a1d3-1c929457e358'
I0624 14:16:28.627012 3822 slave.cpp:1717] Got registration for executor 'default' of framework 20140624-141628-16842879-47356-3799-0000
I0624 14:16:28.627368 3824 replica.cpp:655] Replica received learned notice for position 4
I0624 14:16:28.628049 3819 exec.cpp:205] Executor registered on slave 20140624-141628-16842879-47356-3799-0
I0624 14:16:28.628319 3824 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 789889ns
I0624 14:16:28.628372 3824 leveldb.cpp:401] Deleting ~2 keys from leveldb took 41985ns
I0624 14:16:28.628393 3824 replica.cpp:676] Persisted action at 4
I0624 14:16:28.628401 3824 replica.cpp:661] Replica learned TRUNCATE action at position 4
I0624 14:16:28.629724 3819 exec.cpp:217] Executor::registered took 26577ns
I0624 14:16:28.630137 3822 slave.cpp:1836] Flushing queued task 0 for executor 'default' of framework 20140624-141628-16842879-47356-3799-0000
I0624 14:16:28.630496 3818 exec.cpp:292] Executor asked to run task '0'
I0624 14:16:28.630885 3818 exec.cpp:301] Executor::launchTask took 47686ns
I0624 14:16:28.632346 3818 exec.cpp:524] Executor sending status update TASK_RUNNING (UUID: a55b0564-2adc-43cd-b138-e77c70a45a1c) for task 0 of framework 20140624-141628-16842879-47356-3799-0000
I0624 14:16:28.632741 3822 slave.cpp:2453] Monitoring executor 'default' of framework '20140624-141628-16842879-47356-3799-0000' in container '3e46be2b-35b9-4893-a1d3-1c929457e358'
I0624 14:16:28.633257 3822 slave.cpp:2071] Handling status update TASK_RUNNING (UUID: a55b0564-2adc-43cd-b138-e77c70a45a1c) for task 0 of framework 20140624-141628-16842879-47356-3799-0000 from executor(56)@127.0.1.1:47356
I0624 14:16:28.633641 3824 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: a55b0564-2adc-43cd-b138-e77c70a45a1c) for task 0 of framework 20140624-141628-16842879-47356-3799-0000
I0624 14:16:28.633668 3824 status_update_manager.cpp:499] Creating StatusUpdate stream for task 0 of framework 20140624-141628-16842879-47356-3799-0000
I0624 14:16:28.633757 3824 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: a55b0564-2adc-43cd-b138-e77c70a45a1c) for task 0 of framework 20140624-141628-16842879-47356-3799-0000 to master@127.0.1.1:47356
I0624 14:16:28.633905 3824 master.cpp:3107] Status update TASK_RUNNING (UUID: a55b0564-2adc-43cd-b138-e77c70a45a1c) for task 0 of framework 20140624-141628-16842879-47356-3799-0000 from slave 20140624-141628-16842879-47356-3799-0 at slave(172)@127.0.1.1:47356 (saucy)
I0624 14:16:28.633980 3824 sched.cpp:637] Scheduler::statusUpdate took 24602ns
I0624 14:16:28.634037 3824 master.cpp:2631] Forwarding status update acknowledgement a55b0564-2adc-43cd-b138-e77c70a45a1c for task 0 of framework 20140624-141628-16842879-47356-3799-0000 to slave 20140624-141628-16842879-47356-3799-0 at slave(172)@127.0.1.1:47356 (saucy)
I0624 14:16:28.634171 3799 master.cpp:619] Master terminating
I0624 14:16:28.634219 3799 master.hpp:784] Removing task 0 with resources cpus(*):1; mem(*):500 on slave 20140624-141628-16842879-47356-3799-0 (saucy)
W0624 14:16:28.634274 3799 master.cpp:4253] Removing task 0 of framework 20140624-141628-16842879-47356-3799-0000 and slave 20140624-141628-16842879-47356-3799-0 in non-terminal state TASK_RUNNING
I0624 14:16:28.634807 3824 hierarchical_allocator_process.hpp:635] Recovered cpus(*):1; mem(*):500 (total allocatable: cpus(*):2; mem(*):1024; disk(*):24988; ports(*):[31000-32000]) on slave 20140624-141628-16842879-47356-3799-0 from framework 20140624-141628-16842879-47356-3799-0000
2014-06-24 14:16:28,636:3799(0x2ba5bad079c0):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x146cfbcb1c00000 to [127.0.0.1:36775]
2014-06-24 14:16:28,637:3799(0x2ba5bad079c0):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x146cfbcb1c00003 to [127.0.0.1:36775]
I0624 14:16:28.638485 3799 contender.cpp:186] Now cancelling the membership: 1
2014-06-24 14:16:28,638:3799(0x2ba5bad079c0):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x146cfbcb1c00001 to [127.0.0.1:36775]
I0624 14:16:28.642349 3817 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
I0624 14:16:28.642406 3817 detector.cpp:126] The current leader (id=1) is lost
I0624 14:16:28.642416 3817 detector.cpp:138] Detected a new leader: None
I0624 14:16:28.643342 3823 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
2014-06-24 14:16:28,643:3799(0x2ba5bad079c0):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x146cfbcb1c00002 to [127.0.0.1:36775]
I0624 14:16:28.645526 3820 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
I0624 14:16:28.645576 3820 detector.cpp:126] The current leader (id=1) is lost
I0624 14:16:28.645583 3820 detector.cpp:138] Detected a new leader: None
I0624 14:16:28.645681 3820 sched.cpp:229] Scheduler::disconnected took 27185ns
I0624 14:16:28.645694 3820 sched.cpp:251] No master detected
I0624 14:16:28.647212 3823 status_update_manager.cpp:398] Received status update acknowledgement (UUID: a55b0564-2adc-43cd-b138-e77c70a45a1c) for task 0 of framework 20140624-141628-16842879-47356-3799-0000
I0624 14:16:28.647862 3822 slave.cpp:2315] master@127.0.1.1:47356 exited
W0624 14:16:28.648238 3822 slave.cpp:2318] Master disconnected! Waiting for a new master to be elected
I0624 14:16:28.648494 3822 slave.cpp:629] Lost leading master
I0624 14:16:28.648744 3822 slave.cpp:633] Detecting new master
I0624 14:16:28.649238 3822 slave.cpp:2229] Status update manager successfully handled status update TASK_RUNNING (UUID: a55b0564-2adc-43cd-b138-e77c70a45a1c) for task 0 of framework 20140624-141628-16842879-47356-3799-0000
I0624 14:16:28.649667 3822 slave.cpp:2235] Sending acknowledgement for status update TASK_RUNNING (UUID: a55b0564-2adc-43cd-b138-e77c70a45a1c) for task 0 of framework 20140624-141628-16842879-47356-3799-0000 to executor(56)@127.0.1.1:47356
I0624 14:16:28.650110 3820 exec.cpp:338] Executor received status update acknowledgement a55b0564-2adc-43cd-b138-e77c70a45a1c for task 0 of framework 20140624-141628-16842879-47356-3799-0000
I0624 14:16:28.650480 3799 leveldb.cpp:176] Opened db in 6.150214ms
I0624 14:16:28.650665 3822 slave.cpp:1657] Status update manager successfully handled status update acknowledgement (UUID: a55b0564-2adc-43cd-b138-e77c70a45a1c) for task 0 of framework 20140624-141628-16842879-47356-3799-0000
I0624 14:16:28.653166 3799 leveldb.cpp:183] Compacted db in 2.305728ms
I0624 14:16:28.653549 3799 leveldb.cpp:198] Created db iterator in 17180ns
I0624 14:16:28.653823 3799 leveldb.cpp:204] Seeked to beginning of db in 21313ns
I0624 14:16:28.654105 3799 leveldb.cpp:273] Iterated through 3 keys in the db in 38381ns
I0624 14:16:28.654374 3799 replica.cpp:741] Replica recovered with log positions 3 -> 4 with 0 holes and 0 unlearned
2014-06-24 14:16:28,654:3799(0x2ba5c35d5700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
2014-06-24 14:16:28,654:3799(0x2ba5c35d5700):ZOO_INFO@log_env@716: Client environment:host.name=saucy
2014-06-24 14:16:28,654:3799(0x2ba5c35d5700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
2014-06-24 14:16:28,654:3799(0x2ba5c35d5700):ZOO_INFO@log_env@724: Client environment:os.arch=3.11.0-23-generic
2014-06-24 14:16:28,654:3799(0x2ba5c35d5700):ZOO_INFO@log_env@725: Client environment:os.version=#40-Ubuntu SMP Wed Jun 4 21:05:23 UTC 2014
2014-06-24 14:16:28,654:3799(0x2ba5c35d5700):ZOO_INFO@log_env@733: Client environment:user.name=jenkins
2014-06-24 14:16:28,654:3799(0x2ba5c35d5700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
2014-06-24 14:16:28,655:3799(0x2ba5c35d5700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_bhNlHH
2014-06-24 14:16:28,655:3799(0x2ba5c35d5700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:36775 sessionTimeout=10000 watcher=0x2ba5bb82b610 sessionId=0 sessionPasswd=<null> context=0x2ba5d006a1d0 flags=0
2014-06-24 14:16:28,655:3799(0x2ba5c2bd0700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
2014-06-24 14:16:28,655:3799(0x2ba5c2bd0700):ZOO_INFO@log_env@716: Client environment:host.name=saucy
2014-06-24 14:16:28,655:3799(0x2ba5c2bd0700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
2014-06-24 14:16:28,655:3799(0x2ba5c2bd0700):ZOO_INFO@log_env@724: Client environment:os.arch=3.11.0-23-generic
2014-06-24 14:16:28,655:3799(0x2ba5c2bd0700):ZOO_INFO@log_env@725: Client environment:os.version=#40-Ubuntu SMP Wed Jun 4 21:05:23 UTC 2014
2014-06-24 14:16:28,655:3799(0x2ba5c2bd0700):ZOO_INFO@log_env@733: Client environment:user.name=jenkins
2014-06-24 14:16:28,655:3799(0x2ba5c2bd0700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
2014-06-24 14:16:28,655:3799(0x2ba5c2bd0700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_bhNlHH
2014-06-24 14:16:28,655:3799(0x2ba5c2bd0700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:36775 sessionTimeout=10000 watcher=0x2ba5bb82b610 sessionId=0 sessionPasswd=<null> context=0x2ba5d409fc70 flags=0
I0624 14:16:28.656026 3823 log.cpp:238] Attempting to join replica to ZooKeeper group
I0624 14:16:28.656158 3823 recover.cpp:425] Starting replica recovery
I0624 14:16:28.656237 3823 recover.cpp:451] Replica is in VOTING status
I0624 14:16:28.656275 3823 recover.cpp:440] Recover process terminated
2014-06-24 14:16:28,657:3799(0x2ba5c2dd1700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
2014-06-24 14:16:28,657:3799(0x2ba5c2dd1700):ZOO_INFO@log_env@716: Client environment:host.name=saucy
2014-06-24 14:16:28,657:3799(0x2ba5c2dd1700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
2014-06-24 14:16:28,657:3799(0x2ba5c2dd1700):ZOO_INFO@log_env@724: Client environment:os.arch=3.11.0-23-generic
2014-06-24 14:16:28,657:3799(0x2ba5c2dd1700):ZOO_INFO@log_env@725: Client environment:os.version=#40-Ubuntu SMP Wed Jun 4 21:05:23 UTC 2014
2014-06-24 14:16:28,657:3799(0x2ba5c2dd1700):ZOO_INFO@log_env@733: Client environment:user.name=jenkins
2014-06-24 14:16:28,657:3799(0x2ba5c2dd1700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
2014-06-24 14:16:28,657:3799(0x2ba5c2dd1700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_bhNlHH
2014-06-24 14:16:28,657:3799(0x2ba5c2dd1700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:36775 sessionTimeout=10000 watcher=0x2ba5bb82b610 sessionId=0 sessionPasswd=<null> context=0x2ba5e411e170 flags=0
2014-06-24 14:16:28,657:3799(0x2ba5c33d4700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
2014-06-24 14:16:28,657:3799(0x2ba5c33d4700):ZOO_INFO@log_env@716: Client environment:host.name=saucy
2014-06-24 14:16:28,657:3799(0x2ba5c33d4700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
2014-06-24 14:16:28,657:3799(0x2ba5c33d4700):ZOO_INFO@log_env@724: Client environment:os.arch=3.11.0-23-generic
2014-06-24 14:16:28,657:3799(0x2ba5c33d4700):ZOO_INFO@log_env@725: Client environment:os.version=#40-Ubuntu SMP Wed Jun 4 21:05:23 UTC 2014
2014-06-24 14:16:28,658:3799(0x2ba5c33d4700):ZOO_INFO@log_env@733: Client environment:user.name=jenkins
2014-06-24 14:16:28,658:3799(0x2ba5c33d4700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
2014-06-24 14:16:28,658:3799(0x2ba5c33d4700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_bhNlHH
2014-06-24 14:16:28,658:3799(0x2ba5c33d4700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:36775 sessionTimeout=10000 watcher=0x2ba5bb82b610 sessionId=0 sessionPasswd=<null> context=0x2ba5e40faf00 flags=0
I0624 14:16:28.659212 3821 master.cpp:288] Master 20140624-141628-16842879-47356-3799 (saucy) started on 127.0.1.1:47356
I0624 14:16:28.659243 3821 master.cpp:325] Master only allowing authenticated frameworks to register
I0624 14:16:28.659250 3821 master.cpp:330] Master only allowing authenticated slaves to register
I0624 14:16:28.659256 3821 credentials.hpp:35] Loading credentials for authentication from '/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_bhNlHH/credentials'
I0624 14:16:28.659327 3821 master.cpp:356] Authorization enabled
I0624 14:16:28.659759 3821 master.cpp:122] No whitelist given. Advertising offers for all slaves
I0624 14:16:28.659991 3821 hierarchical_allocator_process.hpp:301] Initializing hierarchical allocator process with master : master@127.0.1.1:47356
I0624 14:16:28.660033 3821 contender.cpp:131] Joining the ZK group
2014-06-24 14:16:28,665:3799(0x2ba5ed754700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:36775]
2014-06-24 14:16:28,669:3799(0x2ba5ed352700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:36775]
2014-06-24 14:16:28,670:3799(0x2ba5ed352700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:36775], sessionId=0x146cfbcb1c00007, negotiated timeout=10000
I0624 14:16:28.671156 3823 group.cpp:313] Group process (group(66)@127.0.1.1:47356) connected to ZooKeeper
I0624 14:16:28.671181 3823 group.cpp:787] Syncing group operations: queue size (joins, cancels, datas) = (0, 0, 0)
I0624 14:16:28.671190 3823 group.cpp:385] Trying to create path '/znode' in ZooKeeper
2014-06-24 14:16:28,669:3799(0x2ba5ec93d700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:36775]
2014-06-24 14:16:28,671:3799(0x2ba5ec93d700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:36775], sessionId=0x146cfbcb1c00006, negotiated timeout=10000
I0624 14:16:28.671772 3819 group.cpp:313] Group process (group(65)@127.0.1.1:47356) connected to ZooKeeper
I0624 14:16:28.671792 3819 group.cpp:787] Syncing group operations: queue size (joins, cancels, datas) = (1, 0, 0)
I0624 14:16:28.671797 3819 group.cpp:385] Trying to create path '/znode' in ZooKeeper
2014-06-24 14:16:28,672:3799(0x2ba5ed754700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:36775], sessionId=0x146cfbcb1c00008, negotiated timeout=10000
I0624 14:16:28.673352 3820 group.cpp:313] Group process (group(64)@127.0.1.1:47356) connected to ZooKeeper
I0624 14:16:28.673372 3820 group.cpp:787] Syncing group operations: queue size (joins, cancels, datas) = (1, 0, 0)
I0624 14:16:28.673378 3820 group.cpp:385] Trying to create path '/znode/log_replicas' in ZooKeeper
2014-06-24 14:16:28,679:3799(0x2ba5edf58700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:36775]
2014-06-24 14:16:28,684:3799(0x2ba5edf58700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:36775], sessionId=0x146cfbcb1c00009, negotiated timeout=10000
I0624 14:16:28.686270 3824 group.cpp:313] Group process (group(63)@127.0.1.1:47356) connected to ZooKeeper
I0624 14:16:28.686297 3824 group.cpp:787] Syncing group operations: queue size (joins, cancels, datas) = (0, 0, 0)
I0624 14:16:28.686305 3824 group.cpp:385] Trying to create path '/znode/log_replicas' in ZooKeeper
I0624 14:16:28.690206 3823 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
I0624 14:16:28.690333 3823 contender.cpp:247] New candidate (id='2') has entered the contest for leadership
I0624 14:16:28.690433 3823 detector.cpp:138] Detected a new leader: (id='2')
I0624 14:16:28.690616 3823 group.cpp:658] Trying to get '/znode/info_0000000002' in ZooKeeper
I0624 14:16:28.690829 3818 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
I0624 14:16:28.690979 3818 detector.cpp:138] Detected a new leader: (id='2')
I0624 14:16:28.691071 3818 group.cpp:658] Trying to get '/znode/info_0000000002' in ZooKeeper
I0624 14:16:28.692811 3823 detector.cpp:382] A new leading master (UPID=master@127.0.1.1:47356) is detected
I0624 14:16:28.692898 3823 master.cpp:1122] The newly elected leader is master@127.0.1.1:47356 with id 20140624-141628-16842879-47356-3799
I0624 14:16:28.692913 3823 master.cpp:1135] Elected as the leading master!
I0624 14:16:28.692919 3823 master.cpp:953] Recovering from registrar
I0624 14:16:28.692980 3823 registrar.cpp:313] Recovering registrar
I0624 14:16:28.693277 3823 log.cpp:656] Attempting to start the writer
I0624 14:16:28.693663 3823 replica.cpp:474] Replica received implicit promise request with proposal 2
I0624 14:16:28.694542 3823 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 872076ns
I0624 14:16:28.694901 3823 replica.cpp:342] Persisted promised to 2
I0624 14:16:28.695360 3823 coordinator.cpp:230] Coordinator attemping to fill missing position
I0624 14:16:28.695710 3823 log.cpp:672] Writer started with ending position 4
I0624 14:16:28.696234 3823 leveldb.cpp:438] Reading position from leveldb took 54720ns
I0624 14:16:28.696511 3823 leveldb.cpp:438] Reading position from leveldb took 28073ns
I0624 14:16:28.697046 3823 registrar.cpp:346] Successfully fetched the registry (248B)
I0624 14:16:28.697345 3823 registrar.cpp:422] Attempting to update the 'registry'
I0624 14:16:28.698782 3819 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
I0624 14:16:28.699357 3821 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
I0624 14:16:28.699414 3821 detector.cpp:138] Detected a new leader: (id='2')
I0624 14:16:28.699604 3821 group.cpp:658] Trying to get '/znode/info_0000000002' in ZooKeeper
I0624 14:16:28.701390 3818 detector.cpp:382] A new leading master (UPID=master@127.0.1.1:47356) is detected
I0624 14:16:28.701479 3818 sched.cpp:235] New master detected at master@127.0.1.1:47356
I0624 14:16:28.701495 3818 sched.cpp:285] Authenticating with master master@127.0.1.1:47356
I0624 14:16:28.701577 3818 authenticatee.hpp:128] Creating new client SASL connection
I0624 14:16:28.701730 3818 master.cpp:843] Dropping 'mesos.internal.AuthenticateMessage' message since not recovered yet
I0624 14:16:28.702262 3820 log.cpp:680] Attempting to append 287 bytes to the log
I0624 14:16:28.702312 3820 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 5
I0624 14:16:28.702520 3820 replica.cpp:508] Replica received write request for position 5
I0624 14:16:28.703209 3820 leveldb.cpp:343] Persisting action (306 bytes) to leveldb took 682429ns
I0624 14:16:28.703230 3820 replica.cpp:676] Persisted action at 5
I0624 14:16:28.703706 3819 replica.cpp:655] Replica received learned notice for position 5
I0624 14:16:28.704243 3819 leveldb.cpp:343] Persisting action (308 bytes) to leveldb took 528201ns
I0624 14:16:28.704262 3819 replica.cpp:676] Persisted action at 5
I0624 14:16:28.704270 3819 replica.cpp:661] Replica learned APPEND action at position 5
I0624 14:16:28.704527 3819 log.cpp:699] Attempting to truncate the log to 5
I0624 14:16:28.704567 3819 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 6
I0624 14:16:28.704752 3819 replica.cpp:508] Replica received write request for position 6
I0624 14:16:28.705055 3819 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 297079ns
I0624 14:16:28.705075 3819 replica.cpp:676] Persisted action at 6
I0624 14:16:28.705242 3819 replica.cpp:655] Replica received learned notice for position 6
I0624 14:16:28.705595 3819 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 347257ns
I0624 14:16:28.705631 3819 leveldb.cpp:401] Deleting ~2 keys from leveldb took 23712ns
I0624 14:16:28.705642 3819 replica.cpp:676] Persisted action at 6
I0624 14:16:28.705648 3819 replica.cpp:661] Replica learned TRUNCATE action at position 6
I0624 14:16:28.715582 3823 registrar.cpp:479] Successfully updated 'registry'
I0624 14:16:28.715639 3823 registrar.cpp:372] Successfully recovered registrar
I0624 14:16:28.715744 3823 master.cpp:980] Recovered 1 slaves from the Registry (248B) ; allowing 10mins for slaves to re-register
I0624 14:16:28.716153 3824 network.hpp:423] ZooKeeper group memberships changed
I0624 14:16:28.716246 3824 group.cpp:658] Trying to get '/znode/log_replicas/0000000001' in ZooKeeper
I0624 14:16:28.716464 3821 detector.cpp:382] A new leading master (UPID=master@127.0.1.1:47356) is detected
I0624 14:16:28.716555 3821 slave.cpp:584] New master detected at master@127.0.1.1:47356
I0624 14:16:28.716578 3821 slave.cpp:660] Authenticating with master master@127.0.1.1:47356
I0624 14:16:28.716617 3821 slave.cpp:633] Detecting new master
I0624 14:16:28.716657 3821 status_update_manager.cpp:167] New master detected at master@127.0.1.1:47356
I0624 14:16:28.716689 3821 authenticatee.hpp:128] Creating new client SASL connection
I0624 14:16:28.717846 3824 network.hpp:461] ZooKeeper group PIDs: { log-replica(375)@127.0.1.1:47356 }
I0624 14:16:28.718163 3821 master.cpp:3499] Authenticating slave(172)@127.0.1.1:47356
I0624 14:16:28.718472 3821 authenticator.hpp:156] Creating new server SASL connection
I0624 14:16:28.718585 3821 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
I0624 14:16:28.718606 3821 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
I0624 14:16:28.718629 3821 authenticator.hpp:262] Received SASL authentication start
I0624 14:16:28.718679 3821 authenticator.hpp:384] Authentication requires more steps
I0624 14:16:28.718706 3821 authenticatee.hpp:265] Received SASL authentication step
I0624 14:16:28.719070 3821 authenticator.hpp:290] Received SASL authentication step
I0624 14:16:28.719110 3821 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
I0624 14:16:28.719120 3821 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I0624 14:16:28.719130 3821 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0624 14:16:28.719140 3821 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
I0624 14:16:28.719146 3821 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0624 14:16:28.719149 3821 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0624 14:16:28.719161 3821 authenticator.hpp:376] Authentication success
I0624 14:16:28.719187 3821 authenticatee.hpp:305] Authentication success
I0624 14:16:28.719208 3821 master.cpp:3539] Successfully authenticated principal 'test-principal' at slave(172)@127.0.1.1:47356
I0624 14:16:28.719274 3821 slave.cpp:717] Successfully authenticated with master master@127.0.1.1:47356
I0624 14:16:28.719359 3821 slave.cpp:955] Will retry registration in 16.70687ms if necessary
I0624 14:16:28.737064 3824 slave.cpp:955] Will retry registration in 836709ns if necessary
I0624 14:16:28.738349 3824 slave.cpp:955] Will retry registration in 50.258054ms if necessary
I0624 14:16:28.789937 3824 slave.cpp:955] Will retry registration in 37.861424ms if necessary
I0624 14:16:28.828560 3824 slave.cpp:955] Will retry registration in 61.927777ms if necessary
I0624 14:16:28.891247 3822 slave.cpp:955] Will retry registration in 525.490436ms if necessary
I0624 14:16:29.417479 3822 slave.cpp:955] Will retry registration in 494.89201ms if necessary
I0624 14:16:29.661031 3822 hierarchical_allocator_process.hpp:724] No resources available to allocate!
I0624 14:16:29.661070 3822 hierarchical_allocator_process.hpp:686] Performed allocation for 0 slaves in 55599ns
I0624 14:16:29.913538 3822 slave.cpp:955] Will retry registration in 171.415002ms if necessary
I0624 14:16:30.085468 3819 slave.cpp:955] Will retry registration in 981.667588ms if necessary
I0624 14:16:30.661633 3823 hierarchical_allocator_process.hpp:724] No resources available to allocate!
I0624 14:16:30.661682 3823 hierarchical_allocator_process.hpp:686] Performed allocation for 0 slaves in 77271ns
I0624 14:16:31.068439 3819 slave.cpp:955] Will retry registration in 1.41897151secs if necessary
2014-06-24 14:16:31,246:3799(0x2ba5ed955700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:44168] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
I0624 14:16:31.662346 3820 hierarchical_allocator_process.hpp:724] No resources available to allocate!
I0624 14:16:31.662389 3820 hierarchical_allocator_process.hpp:686] Performed allocation for 0 slaves in 84812ns
I0624 14:16:32.488217 3817 slave.cpp:955] Will retry registration in 20.015832977secs if necessary
I0624 14:16:32.663578 3823 hierarchical_allocator_process.hpp:724] No resources available to allocate!
I0624 14:16:32.663619 3823 hierarchical_allocator_process.hpp:686] Performed allocation for 0 slaves in 54256ns
I0624 14:16:33.660779 3823 master.cpp:122] No whitelist given. Advertising offers for all slaves
I0624 14:16:33.664497 3822 hierarchical_allocator_process.hpp:724] No resources available to allocate!
I0624 14:16:33.664520 3822 hierarchical_allocator_process.hpp:686] Performed allocation for 0 slaves in 39749ns
W0624 14:16:33.702227 3817 sched.cpp:380] Authentication timed out
I0624 14:16:33.702352 3817 sched.cpp:340] Failed to authenticate with master master@127.0.1.1:47356: Authentication discarded
I0624 14:16:33.702385 3817 sched.cpp:285] Authenticating with master master@127.0.1.1:47356
I0624 14:16:33.702460 3817 authenticatee.hpp:128] Creating new client SASL connection
I0624 14:16:33.703197 3817 master.cpp:3499] Authenticating scheduler-40f24577-8f86-45de-8e3e-7d64238547c1@127.0.1.1:47356
I0624 14:16:33.703312 3817 authenticator.hpp:156] Creating new server SASL connection
I0624 14:16:33.703853 3817 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
I0624 14:16:33.703878 3817 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
I0624 14:16:33.703904 3817 authenticator.hpp:262] Received SASL authentication start
I0624 14:16:33.703975 3817 authenticator.hpp:384] Authentication requires more steps
I0624 14:16:33.704004 3817 authenticatee.hpp:265] Received SASL authentication step
I0624 14:16:33.704036 3817 authenticator.hpp:290] Received SASL authentication step
I0624 14:16:33.704052 3817 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
I0624 14:16:33.704061 3817 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I0624 14:16:33.704072 3817 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0624 14:16:33.704082 3817 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
I0624 14:16:33.704087 3817 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0624 14:16:33.704092 3817 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0624 14:16:33.704102 3817 authenticator.hpp:376] Authentication success
I0624 14:16:33.704126 3817 authenticatee.hpp:305] Authentication success
I0624 14:16:33.704148 3817 master.cpp:3539] Successfully authenticated principal 'test-principal' at scheduler-40f24577-8f86-45de-8e3e-7d64238547c1@127.0.1.1:47356
I0624 14:16:33.704216 3817 sched.cpp:359] Successfully authenticated with master master@127.0.1.1:47356
I0624 14:16:33.704228 3817 sched.cpp:478] Sending registration request to master@127.0.1.1:47356
I0624 14:16:33.704277 3817 master.cpp:1349] Received re-registration request from framework 20140624-141628-16842879-47356-3799-0000 at scheduler-40f24577-8f86-45de-8e3e-7d64238547c1@127.0.1.1:47356
I0624 14:16:33.704291 3817 master.cpp:1201] Authorizing framework principal 'test-principal' to receive offers for role '*'
I0624 14:16:33.704396 3817 master.cpp:1400] Re-registering framework 20140624-141628-16842879-47356-3799-0000 at scheduler-40f24577-8f86-45de-8e3e-7d64238547c1@127.0.1.1:47356
I0624 14:16:33.704697 3819 hierarchical_allocator_process.hpp:331] Added framework 20140624-141628-16842879-47356-3799-0000
I0624 14:16:33.704713 3819 hierarchical_allocator_process.hpp:724] No resources available to allocate!
I0624 14:16:33.704718 3819 hierarchical_allocator_process.hpp:686] Performed allocation for 0 slaves in 9843ns
I0624 14:16:33.705216 3817 sched.cpp:409] Framework registered with 20140624-141628-16842879-47356-3799-0000
I0624 14:16:33.705247 3817 sched.cpp:423] Scheduler::registered took 15606ns
2014-06-24 14:16:34,582:3799(0x2ba5ed955700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:44168] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
I0624 14:16:34.665074 3822 hierarchical_allocator_process.hpp:724] No resources available to allocate!
I0624 14:16:34.665127 3822 hierarchical_allocator_process.hpp:686] Performed allocation for 0 slaves in 86350ns
I0624 14:16:35.665982 3822 hierarchical_allocator_process.hpp:724] No resources available to allocate!
I0624 14:16:35.666025 3822 hierarchical_allocator_process.hpp:686] Performed allocation for 0 slaves in 71358ns
I0624 14:16:36.666646 3824 hierarchical_allocator_process.hpp:724] No resources available to allocate!
I0624 14:16:36.666689 3824 hierarchical_allocator_process.hpp:686] Performed allocation for 0 slaves in 74076ns
I0624 14:16:37.667083 3820 hierarchical_allocator_process.hpp:724] No resources available to allocate!
I0624 14:16:37.667143 3820 hierarchical_allocator_process.hpp:686] Performed allocation for 0 slaves in 89809ns
2014-06-24 14:16:37,919:3799(0x2ba5ed955700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:44168] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
I0624 14:16:38.661608 3820 master.cpp:122] No whitelist given. Advertising offers for all slaves
I0624 14:16:38.668211 3824 hierarchical_allocator_process.hpp:724] No resources available to allocate!
I0624 14:16:38.668238 3824 hierarchical_allocator_process.hpp:686] Performed allocation for 0 slaves in 49135ns
I0624 14:16:39.669014 3822 hierarchical_allocator_process.hpp:724] No resources available to allocate!
I0624 14:16:39.669060 3822 hierarchical_allocator_process.hpp:686] Performed allocation for 0 slaves in 76278ns
I0624 14:16:40.669844 3824 hierarchical_allocator_process.hpp:724] No resources available to allocate!
I0624 14:16:40.669889 3824 hierarchical_allocator_process.hpp:686] Performed allocation for 0 slaves in 74562ns
2014-06-24 14:16:41,256:3799(0x2ba5ed955700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:44168] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
I0624 14:16:41.670398 3820 hierarchical_allocator_process.hpp:724] No resources available to allocate!
I0624 14:16:41.670442 3820 hierarchical_allocator_process.hpp:686] Performed allocation for 0 slaves in 77336ns
I0624 14:16:42.670644 3818 hierarchical_allocator_process.hpp:724] No resources available to allocate!
I0624 14:16:42.670701 3818 hierarchical_allocator_process.hpp:686] Performed allocation for 0 slaves in 109457ns
I0624 14:16:43.662587 3819 master.cpp:122] No whitelist given. Advertising offers for all slaves
I0624 14:16:43.671906 3819 hierarchical_allocator_process.hpp:724] No resources available to allocate!
I0624 14:16:43.671933 3819 hierarchical_allocator_process.hpp:686] Performed allocation for 0 slaves in 43096ns
tests/allocator_zookeeper_tests.cpp:151: Failure
Failed to wait 10secs for resourceOffers2
tests/allocator_zookeeper_tests.cpp:140: Failure
Actual function call count doesn't match EXPECT_CALL(allocator2, slaveAdded(_, _, _))...
Expected: to be called once
Actual: never called - unsatisfied and active
I0624 14:16:43.705966 3823 master.cpp:710] Framework 20140624-141628-16842879-47356-3799-0000 disconnected
I0624 14:16:43.705998 3823 master.cpp:1577] Deactivating framework 20140624-141628-16842879-47356-3799-0000
I0624 14:16:43.706034 3823 master.cpp:732] Giving framework 20140624-141628-16842879-47356-3799-0000 0ns to failover
lt-mesos-tests: ../3rdparty/libprocess/include/process/c++11/dispatch.hpp:155: void process::dispatch(const PID<mesos::internal::master::allocator::AllocatorProcess> &, void (mesos::internal::master::allocator::AllocatorProcess::*)(const mesos::FrameworkID &), mesos::FrameworkID)::<anonymous class>::operator()(process::ProcessBase *) const: Assertion `t != __null' failed.
make[3]: *** [check-local] Aborted
make[3]: Leaving directory `/var/jenkins/workspace/mesos-ubuntu-13.10-clang/src'
make[2]: *** [check-am] Error 2
make[2]: Leaving directory `/var/jenkins/workspace/mesos-ubuntu-13.10-clang/src'
make[1]: *** [check] Error 2
make[1]: Leaving directory `/var/jenkins/workspace/mesos-ubuntu-13.10-clang/src'
make: *** [check-recursive] Error 1
Build step 'Execute shell' marked build as failure
erreicht: 6029993
Sending e-mails to: apache-mesos@twitter.com kernel-test@twitter.com
Finished: FAILURE
{code}
--
This message was sent by Atlassian JIRA
(v6.2#6252)