[ https://issues.apache.org/jira/browse/MESOS-1436?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Dominic Hamon resolved MESOS-1436. ---------------------------------- Resolution: Fixed Fix Version/s: 0.20.0 > AllocatorZooKeeperTest/0.SlaveReregistersFirst flaky and can run forever > ------------------------------------------------------------------------ > > Key: MESOS-1436 > URL: https://issues.apache.org/jira/browse/MESOS-1436 > Project: Mesos > Issue Type: Bug > Components: test > Reporter: Yan Xu > Fix For: 0.20.0 > > > {noformat} > [ RUN ] AllocatorZooKeeperTest/0.SlaveReregistersFirst > Using temporary directory > '/tmp/AllocatorZooKeeperTest_0_SlaveReregistersFirst_qNbdLi' > I0528 23:01:30.969173 2525 leveldb.cpp:176] Opened db in 4.455089ms > I0528 23:01:30.969794 2525 leveldb.cpp:183] Compacted db in 460493ns > I0528 23:01:30.969945 2525 leveldb.cpp:198] Created db iterator in 5290ns > I0528 23:01:30.970137 2525 leveldb.cpp:204] Seeked to beginning of db in > 1015ns > I0528 23:01:30.970294 2525 leveldb.cpp:273] Iterated through 0 keys in the > db in 560ns > I0528 23:01:30.970537 2525 replica.cpp:741] Replica recovered with log > positions 0 -> 0 with 1 holes and 0 unlearned > 2014-05-28 23:01:30,971:2525(0x2b2136157700):ZOO_INFO@log_env@712: Client > environment:zookeeper.version=zookeeper C client 3.4.5 > 2014-05-28 23:01:30,971:2525(0x2b2136157700):ZOO_INFO@log_env@716: Client > environment:host.name=trusty > 2014-05-28 23:01:30,971:2525(0x2b2136157700):ZOO_INFO@log_env@723: Client > environment:os.name=Linux > 2014-05-28 23:01:30,971:2525(0x2b2136157700):ZOO_INFO@log_env@724: Client > environment:os.arch=3.13.0-27-generic > 2014-05-28 23:01:30,971:2525(0x2b2136157700):ZOO_INFO@log_env@725: Client > environment:os.version=#50-Ubuntu SMP Thu May 15 18:06:16 UTC 2014 > 2014-05-28 23:01:30,971:2525(0x2b2136157700):ZOO_INFO@log_env@733: Client > environment:user.name=jenkins > 2014-05-28 23:01:30,972:2525(0x2b2136157700):ZOO_INFO@log_env@741: Client > environment:user.home=/home/jenkins > 2014-05-28 23:01:30,972:2525(0x2b2136157700):ZOO_INFO@log_env@753: Client > environment:user.dir=/tmp/AllocatorZooKeeperTest_0_SlaveReregistersFirst_qNbdLi > 2014-05-28 23:01:30,972:2525(0x2b2136157700):ZOO_INFO@zookeeper_init@786: > Initiating client connection, host=127.0.0.1:44966 sessionTimeout=10000 > watcher=0x2b2132ca6890 sessionId=0 sessionPasswd=<null> > context=0x2b215400e7e0 flags=0 > 2014-05-28 23:01:30,974:2525(0x2b2136358700):ZOO_INFO@log_env@712: Client > environment:zookeeper.version=zookeeper C client 3.4.5 > 2014-05-28 23:01:30,974:2525(0x2b2136358700):ZOO_INFO@log_env@716: Client > environment:host.name=trusty > 2014-05-28 23:01:30,974:2525(0x2b2136358700):ZOO_INFO@log_env@723: Client > environment:os.name=Linux > 2014-05-28 23:01:30,974:2525(0x2b2136358700):ZOO_INFO@log_env@724: Client > environment:os.arch=3.13.0-27-generic > 2014-05-28 23:01:30,974:2525(0x2b2136358700):ZOO_INFO@log_env@725: Client > environment:os.version=#50-Ubuntu SMP Thu May 15 18:06:16 UTC 2014 > 2014-05-28 23:01:30,974:2525(0x2b2136358700):ZOO_INFO@log_env@733: Client > environment:user.name=jenkins > 2014-05-28 23:01:30,974:2525(0x2b2136358700):ZOO_INFO@log_env@741: Client > environment:user.home=/home/jenkins > 2014-05-28 23:01:30,974:2525(0x2b2136358700):ZOO_INFO@log_env@753: Client > environment:user.dir=/tmp/AllocatorZooKeeperTest_0_SlaveReregistersFirst_qNbdLi > 2014-05-28 23:01:30,974:2525(0x2b2136358700):ZOO_INFO@zookeeper_init@786: > Initiating client connection, host=127.0.0.1:44966 sessionTimeout=10000 > watcher=0x2b2132ca6890 sessionId=0 sessionPasswd=<null> > context=0x2b2138038920 flags=0 > I0528 23:01:30.975096 2546 log.cpp:238] Attempting to join replica to > ZooKeeper group > I0528 23:01:30.975348 2546 recover.cpp:425] Starting replica recovery > I0528 23:01:30.975419 2546 recover.cpp:451] Replica is in EMPTY status > I0528 23:01:30.975723 2546 replica.cpp:638] Replica in EMPTY status received > a broadcasted recover request > I0528 23:01:30.975800 2546 recover.cpp:188] Received a recover response from > a replica in EMPTY status > I0528 23:01:30.975918 2546 recover.cpp:542] Updating replica status to > STARTING > I0528 23:01:30.976851 2546 leveldb.cpp:306] Persisting metadata (8 bytes) to > leveldb took 851005ns > I0528 23:01:30.976871 2546 replica.cpp:320] Persisted replica status to > STARTING > I0528 23:01:30.977144 2544 recover.cpp:451] Replica is in STARTING status > I0528 23:01:30.977465 2546 replica.cpp:638] Replica in STARTING status > received a broadcasted recover request > I0528 23:01:30.977524 2546 recover.cpp:188] Received a recover response from > a replica in STARTING status > I0528 23:01:30.977612 2546 recover.cpp:542] Updating replica status to VOTING > I0528 23:01:30.977906 2546 leveldb.cpp:306] Persisting metadata (8 bytes) to > leveldb took 231564ns > I0528 23:01:30.978054 2546 replica.cpp:320] Persisted replica status to > VOTING > I0528 23:01:30.978399 2545 recover.cpp:556] Successfully joined the Paxos > group > I0528 23:01:30.978674 2549 recover.cpp:440] Recover process terminated > 2014-05-28 23:01:30,982:2525(0x2b2135d55700):ZOO_INFO@log_env@712: Client > environment:zookeeper.version=zookeeper C client 3.4.5 > 2014-05-28 23:01:30,983:2525(0x2b2135d55700):ZOO_INFO@log_env@716: Client > environment:host.name=trusty > 2014-05-28 23:01:30,983:2525(0x2b2135d55700):ZOO_INFO@log_env@723: Client > environment:os.name=Linux > 2014-05-28 23:01:30,983:2525(0x2b2135d55700):ZOO_INFO@log_env@724: Client > environment:os.arch=3.13.0-27-generic > 2014-05-28 23:01:30,983:2525(0x2b2135d55700):ZOO_INFO@log_env@725: Client > environment:os.version=#50-Ubuntu SMP Thu May 15 18:06:16 UTC 2014 > 2014-05-28 23:01:30,983:2525(0x2b2135d55700):ZOO_INFO@log_env@733: Client > environment:user.name=jenkins > 2014-05-28 23:01:30,983:2525(0x2b2135d55700):ZOO_INFO@log_env@741: Client > environment:user.home=/home/jenkins > 2014-05-28 23:01:30,983:2525(0x2b2135d55700):ZOO_INFO@log_env@753: Client > environment:user.dir=/tmp/AllocatorZooKeeperTest_0_SlaveReregistersFirst_qNbdLi > 2014-05-28 23:01:30,983:2525(0x2b2135d55700):ZOO_INFO@zookeeper_init@786: > Initiating client connection, host=127.0.0.1:44966 sessionTimeout=10000 > watcher=0x2b2132ca6890 sessionId=0 sessionPasswd=<null> > context=0x2b214005e050 flags=0 > 2014-05-28 23:01:30,983:2525(0x2b2135b54700):ZOO_INFO@log_env@712: Client > environment:zookeeper.version=zookeeper C client 3.4.5 > 2014-05-28 23:01:30,983:2525(0x2b2135b54700):ZOO_INFO@log_env@716: Client > environment:host.name=trusty > 2014-05-28 23:01:30,983:2525(0x2b2135b54700):ZOO_INFO@log_env@723: Client > environment:os.name=Linux > 2014-05-28 23:01:30,983:2525(0x2b2135b54700):ZOO_INFO@log_env@724: Client > environment:os.arch=3.13.0-27-generic > 2014-05-28 23:01:30,983:2525(0x2b2135b54700):ZOO_INFO@log_env@725: Client > environment:os.version=#50-Ubuntu SMP Thu May 15 18:06:16 UTC 2014 > 2014-05-28 23:01:30,984:2525(0x2b2135b54700):ZOO_INFO@log_env@733: Client > environment:user.name=jenkins > 2014-05-28 23:01:30,984:2525(0x2b2135b54700):ZOO_INFO@log_env@741: Client > environment:user.home=/home/jenkins > 2014-05-28 23:01:30,984:2525(0x2b2135b54700):ZOO_INFO@log_env@753: Client > environment:user.dir=/tmp/AllocatorZooKeeperTest_0_SlaveReregistersFirst_qNbdLi > 2014-05-28 23:01:30,984:2525(0x2b2135b54700):ZOO_INFO@zookeeper_init@786: > Initiating client connection, host=127.0.0.1:44966 sessionTimeout=10000 > watcher=0x2b2132ca6890 sessionId=0 sessionPasswd=<null> > context=0x2b214801e690 flags=0 > I0528 23:01:30.987109 2544 master.cpp:272] Master > 20140528-230130-16842879-56711-2525 (trusty) started on 127.0.1.1:56711 > I0528 23:01:30.987134 2544 master.cpp:309] Master only allowing > authenticated frameworks to register > I0528 23:01:30.987143 2544 master.cpp:314] Master only allowing > authenticated slaves to register > I0528 23:01:30.987150 2544 credentials.hpp:35] Loading credentials for > authentication from > '/tmp/AllocatorZooKeeperTest_0_SlaveReregistersFirst_qNbdLi/credentials' > I0528 23:01:30.987229 2544 master.cpp:340] Master enabling authorization > I0528 23:01:30.987613 2544 hierarchical_allocator_process.hpp:301] > Initializing hierarchical allocator process with master : > master@127.0.1.1:56711 > I0528 23:01:30.987649 2544 master.cpp:108] No whitelist given. Advertising > offers for all slaves > I0528 23:01:30.987859 2544 contender.cpp:127] Joining the ZK group > 2014-05-28 23:01:30,994:2525(0x2b21600ed700):ZOO_INFO@check_events@1703: > initiated connection to server [127.0.0.1:44966] > 2014-05-28 23:01:30,994:2525(0x2b2160901700):ZOO_INFO@check_events@1703: > initiated connection to server [127.0.0.1:44966] > 2014-05-28 23:01:30,995:2525(0x2b21604ff700):ZOO_INFO@check_events@1703: > initiated connection to server [127.0.0.1:44966] > 2014-05-28 23:01:30,995:2525(0x2b215fceb700):ZOO_INFO@check_events@1703: > initiated connection to server [127.0.0.1:44966] > 2014-05-28 23:01:31,018:2525(0x2b215fceb700):ZOO_INFO@check_events@1750: > session establishment complete on server [127.0.0.1:44966], > sessionId=0x1464691adb10000, negotiated timeout=10000 > I0528 23:01:31.026738 2549 group.cpp:310] Group process > ((940)@127.0.1.1:56711) connected to ZooKeeper > I0528 23:01:31.026772 2549 group.cpp:784] Syncing group operations: queue > size (joins, cancels, datas) = (0, 0, 0) > I0528 23:01:31.026787 2549 group.cpp:382] Trying to create path > '/znode/log_replicas' in ZooKeeper > 2014-05-28 23:01:31,028:2525(0x2b21600ed700):ZOO_INFO@check_events@1750: > session establishment complete on server [127.0.0.1:44966], > sessionId=0x1464691adb10001, negotiated timeout=10000 > I0528 23:01:31.029418 2548 group.cpp:310] Group process > ((942)@127.0.1.1:56711) connected to ZooKeeper > I0528 23:01:31.029439 2548 group.cpp:784] Syncing group operations: queue > size (joins, cancels, datas) = (1, 0, 0) > I0528 23:01:31.029448 2548 group.cpp:382] Trying to create path > '/znode/log_replicas' in ZooKeeper > 2014-05-28 23:01:31,030:2525(0x2b2160901700):ZOO_INFO@check_events@1750: > session establishment complete on server [127.0.0.1:44966], > sessionId=0x1464691adb10002, negotiated timeout=10000 > I0528 23:01:31.031448 2550 group.cpp:310] Group process > ((951)@127.0.1.1:56711) connected to ZooKeeper > I0528 23:01:31.031469 2550 group.cpp:784] Syncing group operations: queue > size (joins, cancels, datas) = (0, 0, 0) > I0528 23:01:31.031478 2550 group.cpp:382] Trying to create path '/znode' in > ZooKeeper > 2014-05-28 23:01:31,032:2525(0x2b21604ff700):ZOO_INFO@check_events@1750: > session establishment complete on server [127.0.0.1:44966], > sessionId=0x1464691adb10003, negotiated timeout=10000 > I0528 23:01:31.033535 2547 group.cpp:310] Group process > ((948)@127.0.1.1:56711) connected to ZooKeeper > I0528 23:01:31.033555 2547 group.cpp:784] Syncing group operations: queue > size (joins, cancels, datas) = (1, 0, 0) > I0528 23:01:31.033565 2547 group.cpp:382] Trying to create path '/znode' in > ZooKeeper > I0528 23:01:31.097532 2550 contender.cpp:243] New candidate (id='0') has > entered the contest for leadership > I0528 23:01:31.100992 2545 group.cpp:711] Found non-sequence node > 'log_replicas' at '/znode' in ZooKeeper > I0528 23:01:31.101076 2545 detector.cpp:135] Detected a new leader: (id='0') > I0528 23:01:31.101272 2545 group.cpp:655] Trying to get > '/znode/info_0000000000' in ZooKeeper > I0528 23:01:31.102300 2547 group.cpp:711] Found non-sequence node > 'log_replicas' at '/znode' in ZooKeeper > I0528 23:01:31.107453 2545 detector.cpp:377] A new leading master > (UPID=master@127.0.1.1:56711) is detected > I0528 23:01:31.107509 2545 master.cpp:957] The newly elected leader is > master@127.0.1.1:56711 with id 20140528-230130-16842879-56711-2525 > I0528 23:01:31.107522 2545 master.cpp:970] Elected as the leading master! > I0528 23:01:31.107529 2545 master.cpp:788] Recovering from registrar > I0528 23:01:31.107585 2545 registrar.cpp:313] Recovering registrar > I0528 23:01:31.107826 2545 log.cpp:656] Attempting to start the writer > I0528 23:01:31.108115 2545 replica.cpp:474] Replica received implicit > promise request with proposal 1 > I0528 23:01:31.109215 2544 network.hpp:423] ZooKeeper group memberships > changed > I0528 23:01:31.109334 2544 group.cpp:655] Trying to get > '/znode/log_replicas/0000000000' in ZooKeeper > I0528 23:01:31.109900 2545 leveldb.cpp:306] Persisting metadata (8 bytes) to > leveldb took 1.761338ms > I0528 23:01:31.109932 2545 replica.cpp:342] Persisted promised to 1 > I0528 23:01:31.110085 2545 coordinator.cpp:230] Coordinator attemping to > fill missing position > I0528 23:01:31.110600 2545 replica.cpp:375] Replica received explicit > promise request for position 0 with proposal 2 > I0528 23:01:31.111697 2545 leveldb.cpp:343] Persisting action (8 bytes) to > leveldb took 1.073287ms > I0528 23:01:31.111722 2545 replica.cpp:676] Persisted action at 0 > I0528 23:01:31.111968 2545 replica.cpp:508] Replica received write request > for position 0 > I0528 23:01:31.111996 2545 leveldb.cpp:438] Reading position from leveldb > took 12438ns > I0528 23:01:31.112372 2545 leveldb.cpp:343] Persisting action (14 bytes) to > leveldb took 359269ns > I0528 23:01:31.112521 2545 replica.cpp:676] Persisted action at 0 > I0528 23:01:31.119140 2547 replica.cpp:655] Replica received learned notice > for position 0 > I0528 23:01:31.119611 2545 network.hpp:461] ZooKeeper group PIDs: { > log-replica(26)@127.0.1.1:56711 } > I0528 23:01:31.120671 2547 leveldb.cpp:343] Persisting action (16 bytes) to > leveldb took 1.503773ms > I0528 23:01:31.120697 2547 replica.cpp:676] Persisted action at 0 > I0528 23:01:31.120895 2547 replica.cpp:661] Replica learned NOP action at > position 0 > I0528 23:01:31.121294 2547 log.cpp:672] Writer started with ending position 0 > I0528 23:01:31.121515 2547 leveldb.cpp:438] Reading position from leveldb > took 10183ns > I0528 23:01:31.126590 2547 registrar.cpp:346] Successfully fetched the > registry (0B) > I0528 23:01:31.126885 2547 registrar.cpp:422] Attempting to update the > 'registry' > I0528 23:01:31.128154 2546 log.cpp:680] Attempting to append 118 bytes to > the log > I0528 23:01:31.128200 2546 coordinator.cpp:340] Coordinator attempting to > write APPEND action at position 1 > I0528 23:01:31.128362 2546 replica.cpp:508] Replica received write request > for position 1 > I0528 23:01:31.128859 2546 leveldb.cpp:343] Persisting action (135 bytes) to > leveldb took 475805ns > I0528 23:01:31.128878 2546 replica.cpp:676] Persisted action at 1 > I0528 23:01:31.129030 2546 replica.cpp:655] Replica received learned notice > for position 1 > I0528 23:01:31.129323 2546 leveldb.cpp:343] Persisting action (137 bytes) to > leveldb took 271504ns > I0528 23:01:31.129343 2546 replica.cpp:676] Persisted action at 1 > I0528 23:01:31.129351 2546 replica.cpp:661] Replica learned APPEND action at > position 1 > I0528 23:01:31.129549 2546 log.cpp:699] Attempting to truncate the log to 1 > I0528 23:01:31.129585 2546 coordinator.cpp:340] Coordinator attempting to > write TRUNCATE action at position 2 > I0528 23:01:31.129734 2546 replica.cpp:508] Replica received write request > for position 2 > I0528 23:01:31.130116 2546 leveldb.cpp:343] Persisting action (16 bytes) to > leveldb took 362587ns > I0528 23:01:31.130136 2546 replica.cpp:676] Persisted action at 2 > I0528 23:01:31.134672 2550 replica.cpp:655] Replica received learned notice > for position 2 > I0528 23:01:31.135171 2547 registrar.cpp:479] Successfully updated 'registry' > I0528 23:01:31.135449 2547 registrar.cpp:372] Successfully recovered > registrar > I0528 23:01:31.135730 2547 master.cpp:815] Recovered 0 slaves from the > Registry (82B) ; allowing 10mins for slaves to re-register > I0528 23:01:31.135622 2550 leveldb.cpp:343] Persisting action (18 bytes) to > leveldb took 924046ns > I0528 23:01:31.138051 2550 leveldb.cpp:401] Deleting ~1 keys from leveldb > took 19299ns > I0528 23:01:31.138068 2550 replica.cpp:676] Persisted action at 2 > I0528 23:01:31.138078 2550 replica.cpp:661] Replica learned TRUNCATE action > at position 2 > I0528 23:01:31.137892 2548 slave.cpp:143] Slave started on > 46)@127.0.1.1:56711 > I0528 23:01:31.138206 2548 credentials.hpp:35] Loading credentials for > authentication from > '/tmp/AllocatorZooKeeperTest_0_SlaveReregistersFirst_FCGlTk/credential' > I0528 23:01:31.138278 2548 slave.cpp:242] Slave using credential for: > test-principal > I0528 23:01:31.138401 2548 slave.cpp:255] Slave resources: cpus(*):2; > mem(*):1024; disk(*):24988; ports(*):[31000-32000] > 2014-05-28 23:01:31,136:2525(0x2b2135953700):ZOO_INFO@log_env@712: Client > environment:zookeeper.version=zookeeper C client 3.4.5 > 2014-05-28 23:01:31,138:2525(0x2b2135953700):ZOO_INFO@log_env@716: Client > environment:host.name=trusty > 2014-05-28 23:01:31,138:2525(0x2b2135953700):ZOO_INFO@log_env@723: Client > environment:os.name=Linux > 2014-05-28 23:01:31,138:2525(0x2b2135953700):ZOO_INFO@log_env@724: Client > environment:os.arch=3.13.0-27-generic > 2014-05-28 23:01:31,138:2525(0x2b2135953700):ZOO_INFO@log_env@725: Client > environment:os.version=#50-Ubuntu SMP Thu May 15 18:06:16 UTC 2014 > 2014-05-28 23:01:31,137:2525(0x2b2135f56700):ZOO_INFO@log_env@712: Client > environment:zookeeper.version=zookeeper C client 3.4.5 > 2014-05-28 23:01:31,138:2525(0x2b2135f56700):ZOO_INFO@log_env@716: Client > environment:host.name=trusty > 2014-05-28 23:01:31,138:2525(0x2b2135f56700):ZOO_INFO@log_env@723: Client > environment:os.name=Linux > 2014-05-28 23:01:31,138:2525(0x2b2135f56700):ZOO_INFO@log_env@724: Client > environment:os.arch=3.13.0-27-generic > 2014-05-28 23:01:31,138:2525(0x2b2135f56700):ZOO_INFO@log_env@725: Client > environment:os.version=#50-Ubuntu SMP Thu May 15 18:06:16 UTC 2014 > 2014-05-28 23:01:31,138:2525(0x2b2135f56700):ZOO_INFO@log_env@733: Client > environment:user.name=jenkins > 2014-05-28 23:01:31,138:2525(0x2b2135f56700):ZOO_INFO@log_env@741: Client > environment:user.home=/home/jenkins > 2014-05-28 23:01:31,138:2525(0x2b2135f56700):ZOO_INFO@log_env@753: Client > environment:user.dir=/tmp/AllocatorZooKeeperTest_0_SlaveReregistersFirst_qNbdLi > 2014-05-28 23:01:31,139:2525(0x2b2135f56700):ZOO_INFO@zookeeper_init@786: > Initiating client connection, host=127.0.0.1:44966 sessionTimeout=10000 > watcher=0x2b2132ca6890 sessionId=0 sessionPasswd=<null> > context=0x2b213c00c1e0 flags=0 > 2014-05-28 23:01:31,139:2525(0x2b2135953700):ZOO_INFO@log_env@733: Client > environment:user.name=jenkins > 2014-05-28 23:01:31,139:2525(0x2b2135953700):ZOO_INFO@log_env@741: Client > environment:user.home=/home/jenkins > 2014-05-28 23:01:31,139:2525(0x2b2135953700):ZOO_INFO@log_env@753: Client > environment:user.dir=/tmp/AllocatorZooKeeperTest_0_SlaveReregistersFirst_qNbdLi > 2014-05-28 23:01:31,139:2525(0x2b2135953700):ZOO_INFO@zookeeper_init@786: > Initiating client connection, host=127.0.0.1:44966 sessionTimeout=10000 > watcher=0x2b2132ca6890 sessionId=0 sessionPasswd=<null> > context=0x2b214c032390 flags=0 > I0528 23:01:31.139881 2548 slave.cpp:283] Slave hostname: trusty > I0528 23:01:31.140270 2548 slave.cpp:284] Slave checkpoint: false > I0528 23:01:31.140605 2548 state.cpp:33] Recovering state from > '/tmp/AllocatorZooKeeperTest_0_SlaveReregistersFirst_FCGlTk/meta' > I0528 23:01:31.140688 2548 status_update_manager.cpp:193] Recovering status > update manager > I0528 23:01:31.140772 2548 slave.cpp:3018] Finished recovery > I0528 23:01:31.137737 2525 sched.cpp:126] Version: 0.19.0 > 2014-05-28 23:01:31,144:2525(0x2b2160d03700):ZOO_INFO@check_events@1703: > initiated connection to server [127.0.0.1:44966] > 2014-05-28 23:01:31,145:2525(0x2b2160d03700):ZOO_INFO@check_events@1750: > session establishment complete on server [127.0.0.1:44966], > sessionId=0x1464691adb10004, negotiated timeout=10000 > I0528 23:01:31.145869 2547 group.cpp:310] Group process > ((969)@127.0.1.1:56711) connected to ZooKeeper > I0528 23:01:31.145889 2547 group.cpp:784] Syncing group operations: queue > size (joins, cancels, datas) = (0, 0, 0) > I0528 23:01:31.145900 2547 group.cpp:382] Trying to create path '/znode' in > ZooKeeper > 2014-05-28 23:01:31,145:2525(0x2b2161105700):ZOO_INFO@check_events@1703: > initiated connection to server [127.0.0.1:44966] > 2014-05-28 23:01:31,146:2525(0x2b2161105700):ZOO_INFO@check_events@1750: > session establishment complete on server [127.0.0.1:44966], > sessionId=0x1464691adb10005, negotiated timeout=10000 > I0528 23:01:31.146834 2546 group.cpp:310] Group process > ((962)@127.0.1.1:56711) connected to ZooKeeper > I0528 23:01:31.146853 2546 group.cpp:784] Syncing group operations: queue > size (joins, cancels, datas) = (0, 0, 0) > I0528 23:01:31.146862 2546 group.cpp:382] Trying to create path '/znode' in > ZooKeeper > I0528 23:01:31.159360 2547 group.cpp:711] Found non-sequence node > 'log_replicas' at '/znode' in ZooKeeper > I0528 23:01:31.159420 2547 detector.cpp:135] Detected a new leader: (id='0') > I0528 23:01:31.159508 2547 group.cpp:655] Trying to get > '/znode/info_0000000000' in ZooKeeper > I0528 23:01:31.161211 2546 group.cpp:711] Found non-sequence node > 'log_replicas' at '/znode' in ZooKeeper > I0528 23:01:31.161262 2546 detector.cpp:135] Detected a new leader: (id='0') > I0528 23:01:31.161335 2546 group.cpp:655] Trying to get > '/znode/info_0000000000' in ZooKeeper > I0528 23:01:31.162050 2547 detector.cpp:377] A new leading master > (UPID=master@127.0.1.1:56711) is detected > I0528 23:01:31.162106 2547 sched.cpp:222] New master detected at > master@127.0.1.1:56711 > I0528 23:01:31.162122 2547 sched.cpp:273] Authenticating with master > master@127.0.1.1:56711 > I0528 23:01:31.162195 2547 authenticatee.hpp:128] Creating new client SASL > connection > I0528 23:01:31.162734 2547 master.cpp:2986] Authenticating > scheduler(27)@127.0.1.1:56711 > I0528 23:01:31.162821 2547 authenticator.hpp:156] Creating new server SASL > connection > I0528 23:01:31.163161 2547 authenticatee.hpp:219] Received SASL > authentication mechanisms: CRAM-MD5 > I0528 23:01:31.163184 2547 authenticatee.hpp:245] Attempting to authenticate > with mechanism 'CRAM-MD5' > I0528 23:01:31.163211 2547 authenticator.hpp:262] Received SASL > authentication start > I0528 23:01:31.163249 2547 authenticator.hpp:384] Authentication requires > more steps > I0528 23:01:31.163275 2547 authenticatee.hpp:265] Received SASL > authentication step > I0528 23:01:31.163310 2547 authenticator.hpp:290] Received SASL > authentication step > I0528 23:01:31.163326 2547 auxprop.cpp:81] Request to lookup properties for > user: 'test-principal' realm: 'trusty' server FQDN: 'trusty' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: false > I0528 23:01:31.163334 2547 auxprop.cpp:153] Looking up auxiliary property > '*userPassword' > I0528 23:01:31.163346 2547 auxprop.cpp:153] Looking up auxiliary property > '*cmusaslsecretCRAM-MD5' > I0528 23:01:31.163355 2547 auxprop.cpp:81] Request to lookup properties for > user: 'test-principal' realm: 'trusty' server FQDN: 'trusty' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: true > I0528 23:01:31.163362 2547 auxprop.cpp:103] Skipping auxiliary property > '*userPassword' since SASL_AUXPROP_AUTHZID == true > I0528 23:01:31.163367 2547 auxprop.cpp:103] Skipping auxiliary property > '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true > I0528 23:01:31.163379 2547 authenticator.hpp:376] Authentication success > I0528 23:01:31.163403 2547 authenticatee.hpp:305] Authentication success > I0528 23:01:31.163424 2547 master.cpp:3026] Successfully authenticated > principal 'test-principal' at scheduler(27)@127.0.1.1:56711 > I0528 23:01:31.163486 2547 sched.cpp:347] Successfully authenticated with > master master@127.0.1.1:56711 > I0528 23:01:31.163501 2547 sched.cpp:466] Sending registration request to > master@127.0.1.1:56711 > I0528 23:01:31.163542 2547 master.cpp:1041] Received registration request > from scheduler(27)@127.0.1.1:56711 > I0528 23:01:31.163574 2547 master.cpp:1059] Registering framework > 20140528-230130-16842879-56711-2525-0000 at scheduler(27)@127.0.1.1:56711 > I0528 23:01:31.163630 2547 sched.cpp:397] Framework registered with > 20140528-230130-16842879-56711-2525-0000 > I0528 23:01:31.163650 2547 sched.cpp:411] Scheduler::registered took 8605ns > I0528 23:01:31.163684 2547 hierarchical_allocator_process.hpp:331] Added > framework 20140528-230130-16842879-56711-2525-0000 > I0528 23:01:31.163694 2547 hierarchical_allocator_process.hpp:725] No > resources available to allocate! > I0528 23:01:31.163700 2547 hierarchical_allocator_process.hpp:687] Performed > allocation for 0 slaves in 6764ns > I0528 23:01:31.164517 2546 detector.cpp:377] A new leading master > (UPID=master@127.0.1.1:56711) is detected > I0528 23:01:31.164572 2546 slave.cpp:536] New master detected at > master@127.0.1.1:56711 > I0528 23:01:31.164592 2546 slave.cpp:612] Authenticating with master > master@127.0.1.1:56711 > I0528 23:01:31.164628 2546 slave.cpp:585] Detecting new master > I0528 23:01:31.164659 2546 status_update_manager.cpp:167] New master > detected at master@127.0.1.1:56711 > I0528 23:01:31.164685 2546 authenticatee.hpp:128] Creating new client SASL > connection > I0528 23:01:31.164811 2546 master.cpp:2986] Authenticating > slave(46)@127.0.1.1:56711 > I0528 23:01:31.164876 2546 authenticator.hpp:156] Creating new server SASL > connection > I0528 23:01:31.164980 2546 authenticatee.hpp:219] Received SASL > authentication mechanisms: CRAM-MD5 > I0528 23:01:31.164999 2546 authenticatee.hpp:245] Attempting to authenticate > with mechanism 'CRAM-MD5' > I0528 23:01:31.165021 2546 authenticator.hpp:262] Received SASL > authentication start > I0528 23:01:31.165051 2546 authenticator.hpp:384] Authentication requires > more steps > I0528 23:01:31.165076 2546 authenticatee.hpp:265] Received SASL > authentication step > I0528 23:01:31.165104 2546 authenticator.hpp:290] Received SASL > authentication step > I0528 23:01:31.165117 2546 auxprop.cpp:81] Request to lookup properties for > user: 'test-principal' realm: 'trusty' server FQDN: 'trusty' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: false > I0528 23:01:31.165124 2546 auxprop.cpp:153] Looking up auxiliary property > '*userPassword' > I0528 23:01:31.165133 2546 auxprop.cpp:153] Looking up auxiliary property > '*cmusaslsecretCRAM-MD5' > I0528 23:01:31.165143 2546 auxprop.cpp:81] Request to lookup properties for > user: 'test-principal' realm: 'trusty' server FQDN: 'trusty' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: true > I0528 23:01:31.165148 2546 auxprop.cpp:103] Skipping auxiliary property > '*userPassword' since SASL_AUXPROP_AUTHZID == true > I0528 23:01:31.165154 2546 auxprop.cpp:103] Skipping auxiliary property > '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true > I0528 23:01:31.165164 2546 authenticator.hpp:376] Authentication success > I0528 23:01:31.165186 2546 authenticatee.hpp:305] Authentication success > I0528 23:01:31.165206 2546 master.cpp:3026] Successfully authenticated > principal 'test-principal' at slave(46)@127.0.1.1:56711 > I0528 23:01:31.165261 2546 slave.cpp:669] Successfully authenticated with > master master@127.0.1.1:56711 > I0528 23:01:31.165302 2546 slave.cpp:902] Will retry registration in > 14.493836ms if necessary > I0528 23:01:31.165391 2550 master.cpp:2302] Registering slave at > slave(46)@127.0.1.1:56711 (trusty) with id > 20140528-230130-16842879-56711-2525-0 > I0528 23:01:31.165484 2550 registrar.cpp:422] Attempting to update the > 'registry' > I0528 23:01:31.166597 2548 log.cpp:680] Attempting to append 290 bytes to > the log > I0528 23:01:31.166643 2548 coordinator.cpp:340] Coordinator attempting to > write APPEND action at position 3 > I0528 23:01:31.166854 2548 replica.cpp:508] Replica received write request > for position 3 > I0528 23:01:31.167264 2548 leveldb.cpp:343] Persisting action (309 bytes) to > leveldb took 388182ns > I0528 23:01:31.167284 2548 replica.cpp:676] Persisted action at 3 > I0528 23:01:31.167439 2548 replica.cpp:655] Replica received learned notice > for position 3 > I0528 23:01:31.168390 2548 leveldb.cpp:343] Persisting action (311 bytes) to > leveldb took 930010ns > I0528 23:01:31.168412 2548 replica.cpp:676] Persisted action at 3 > I0528 23:01:31.168421 2548 replica.cpp:661] Replica learned APPEND action at > position 3 > I0528 23:01:31.168673 2548 registrar.cpp:479] Successfully updated 'registry' > I0528 23:01:31.168738 2548 log.cpp:699] Attempting to truncate the log to 3 > I0528 23:01:31.168784 2548 master.cpp:2342] Registered slave > 20140528-230130-16842879-56711-2525-0 at slave(46)@127.0.1.1:56711 (trusty) > I0528 23:01:31.168800 2548 master.cpp:3472] Adding slave > 20140528-230130-16842879-56711-2525-0 at slave(46)@127.0.1.1:56711 (trusty) > with cpus(*):2; mem(*):1024; disk(*):24988; ports(*):[31000-32000] > I0528 23:01:31.168881 2548 coordinator.cpp:340] Coordinator attempting to > write TRUNCATE action at position 4 > I0528 23:01:31.168939 2548 slave.cpp:703] Registered with master > master@127.0.1.1:56711; given slave ID 20140528-230130-16842879-56711-2525-0 > I0528 23:01:31.168999 2548 hierarchical_allocator_process.hpp:444] Added > slave 20140528-230130-16842879-56711-2525-0 (trusty) with cpus(*):2; > mem(*):1024; disk(*):24988; ports(*):[31000-32000] (and cpus(*):2; > mem(*):1024; disk(*):24988; ports(*):[31000-32000] available) > I0528 23:01:31.169050 2548 hierarchical_allocator_process.hpp:751] Offering > cpus(*):2; mem(*):1024; disk(*):24988; ports(*):[31000-32000] on slave > 20140528-230130-16842879-56711-2525-0 to framework > 20140528-230130-16842879-56711-2525-0000 > I0528 23:01:31.169126 2548 hierarchical_allocator_process.hpp:707] Performed > allocation for slave 20140528-230130-16842879-56711-2525-0 in 96190ns > I0528 23:01:31.169203 2548 master.hpp:683] Adding offer > 20140528-230130-16842879-56711-2525-0 with resources cpus(*):2; mem(*):1024; > disk(*):24988; ports(*):[31000-32000] on slave > 20140528-230130-16842879-56711-2525-0 (trusty) > I0528 23:01:31.169245 2548 master.cpp:2933] Sending 1 offers to framework > 20140528-230130-16842879-56711-2525-0000 > I0528 23:01:31.169461 2548 sched.cpp:534] Scheduler::resourceOffers took > 116834ns > I0528 23:01:31.169615 2548 master.hpp:693] Removing offer > 20140528-230130-16842879-56711-2525-0 with resources cpus(*):2; mem(*):1024; > disk(*):24988; ports(*):[31000-32000] on slave > 20140528-230130-16842879-56711-2525-0 (trusty) > I0528 23:01:31.169664 2548 master.cpp:1889] Processing reply for offers: [ > 20140528-230130-16842879-56711-2525-0 ] on slave > 20140528-230130-16842879-56711-2525-0 at slave(46)@127.0.1.1:56711 (trusty) > for framework 20140528-230130-16842879-56711-2525-0000 > I0528 23:01:31.169745 2548 master.hpp:655] Adding task 0 with resources > cpus(*):1; mem(*):500 on slave 20140528-230130-16842879-56711-2525-0 (trusty) > I0528 23:01:31.169772 2548 master.cpp:3111] Launching task 0 of framework > 20140528-230130-16842879-56711-2525-0000 with resources cpus(*):1; mem(*):500 > on slave 20140528-230130-16842879-56711-2525-0 at slave(46)@127.0.1.1:56711 > (trusty) > I0528 23:01:31.169911 2548 slave.cpp:933] Got assigned task 0 for framework > 20140528-230130-16842879-56711-2525-0000 > I0528 23:01:31.170063 2548 slave.cpp:1043] Launching task 0 for framework > 20140528-230130-16842879-56711-2525-0000 > I0528 23:01:31.170703 2550 hierarchical_allocator_process.hpp:546] Framework > 20140528-230130-16842879-56711-2525-0000 left cpus(*):1; mem(*):524; > disk(*):24988; ports(*):[31000-32000] unused on slave > 20140528-230130-16842879-56711-2525-0 > I0528 23:01:31.171082 2550 hierarchical_allocator_process.hpp:589] Framework > 20140528-230130-16842879-56711-2525-0000 filtered slave > 20140528-230130-16842879-56711-2525-0 for 5secs > I0528 23:01:31.170990 2551 replica.cpp:508] Replica received write request > for position 4 > I0528 23:01:31.171852 2551 leveldb.cpp:343] Persisting action (16 bytes) to > leveldb took 577081ns > I0528 23:01:31.171872 2551 replica.cpp:676] Persisted action at 4 > I0528 23:01:31.172268 2551 replica.cpp:655] Replica received learned notice > for position 4 > I0528 23:01:31.172605 2551 leveldb.cpp:343] Persisting action (18 bytes) to > leveldb took 313596ns > I0528 23:01:31.172642 2551 leveldb.cpp:401] Deleting ~2 keys from leveldb > took 18631ns > I0528 23:01:31.172653 2551 replica.cpp:676] Persisted action at 4 > I0528 23:01:31.172662 2551 replica.cpp:661] Replica learned TRUNCATE action > at position 4 > I0528 23:01:31.174681 2548 exec.cpp:131] Version: 0.19.0 > I0528 23:01:31.175060 2544 exec.cpp:181] Executor started at: > executor(1)@127.0.1.1:56711 with pid 2525 > I0528 23:01:31.175324 2548 slave.cpp:1153] Queuing task '0' for executor > default of framework '20140528-230130-16842879-56711-2525-0000 > I0528 23:01:31.175658 2548 slave.cpp:497] Successfully attached file > '/tmp/AllocatorZooKeeperTest_0_SlaveReregistersFirst_FCGlTk/slaves/20140528-230130-16842879-56711-2525-0/frameworks/20140528-230130-16842879-56711-2525-0000/executors/default/runs/8fdd0ca9-af9b-416a-8507-9112f7aa403d' > I0528 23:01:31.175969 2548 slave.cpp:1664] Got registration for executor > 'default' of framework 20140528-230130-16842879-56711-2525-0000 > I0528 23:01:31.176446 2545 exec.cpp:205] Executor registered on slave > 20140528-230130-16842879-56711-2525-0 > I0528 23:01:31.177356 2545 exec.cpp:217] Executor::registered took 29066ns > I0528 23:01:31.177556 2548 slave.cpp:1783] Flushing queued task 0 for > executor 'default' of framework 20140528-230130-16842879-56711-2525-0000 > I0528 23:01:31.177978 2551 exec.cpp:292] Executor asked to run task '0' > I0528 23:01:31.178040 2551 exec.cpp:301] Executor::launchTask took 42285ns > I0528 23:01:31.179141 2551 exec.cpp:524] Executor sending status update > TASK_RUNNING (UUID: 08ed6d92-b404-4835-9fa8-85df7c809850) for task 0 of > framework 20140528-230130-16842879-56711-2525-0000 > I0528 23:01:31.179358 2548 slave.cpp:2355] Monitoring executor 'default' of > framework '20140528-230130-16842879-56711-2525-0000' in container > '8fdd0ca9-af9b-416a-8507-9112f7aa403d' > I0528 23:01:31.179858 2548 slave.cpp:2018] Handling status update > TASK_RUNNING (UUID: 08ed6d92-b404-4835-9fa8-85df7c809850) for task 0 of > framework 20140528-230130-16842879-56711-2525-0000 from > executor(1)@127.0.1.1:56711 > I0528 23:01:31.180249 2544 status_update_manager.cpp:320] Received status > update TASK_RUNNING (UUID: 08ed6d92-b404-4835-9fa8-85df7c809850) for task 0 > of framework 20140528-230130-16842879-56711-2525-0000 > I0528 23:01:31.180270 2544 status_update_manager.cpp:499] Creating > StatusUpdate stream for task 0 of framework > 20140528-230130-16842879-56711-2525-0000 > I0528 23:01:31.180320 2544 status_update_manager.cpp:373] Forwarding status > update TASK_RUNNING (UUID: 08ed6d92-b404-4835-9fa8-85df7c809850) for task 0 > of framework 20140528-230130-16842879-56711-2525-0000 to > master@127.0.1.1:56711 > I0528 23:01:31.180428 2544 master.cpp:2628] Status update TASK_RUNNING > (UUID: 08ed6d92-b404-4835-9fa8-85df7c809850) for task 0 of framework > 20140528-230130-16842879-56711-2525-0000 from slave > 20140528-230130-16842879-56711-2525-0 at slave(46)@127.0.1.1:56711 (trusty) > I0528 23:01:31.180495 2544 sched.cpp:625] Scheduler::statusUpdate took > 13954ns > I0528 23:01:31.180604 2525 master.cpp:574] Master terminating > I0528 23:01:31.180641 2525 master.hpp:673] Removing task 0 with resources > cpus(*):1; mem(*):500 on slave 20140528-230130-16842879-56711-2525-0 (trusty) > W0528 23:01:31.180707 2525 master.cpp:3758] Removing task 0 of framework > 20140528-230130-16842879-56711-2525-0000 and slave > 20140528-230130-16842879-56711-2525-0 in non-terminal state TASK_RUNNING > 2014-05-28 23:01:31,182:2525(0x2b213233aa80):ZOO_INFO@zookeeper_close@2505: > Closing zookeeper sessionId=0x1464691adb10001 to [127.0.0.1:44966] > 2014-05-28 23:01:31,186:2525(0x2b213233aa80):ZOO_INFO@zookeeper_close@2505: > Closing zookeeper sessionId=0x1464691adb10000 to [127.0.0.1:44966] > I0528 23:01:31.189216 2525 contender.cpp:182] Now cancelling the membership: > 0 > 2014-05-28 23:01:31,189:2525(0x2b213233aa80):ZOO_INFO@zookeeper_close@2505: > Closing zookeeper sessionId=0x1464691adb10003 to [127.0.0.1:44966] > I0528 23:01:31.198542 2549 status_update_manager.cpp:398] Received status > update acknowledgement (UUID: 08ed6d92-b404-4835-9fa8-85df7c809850) for task > 0 of framework 20140528-230130-16842879-56711-2525-0000 > I0528 23:01:31.198971 2548 slave.cpp:2224] master@127.0.1.1:56711 exited > W0528 23:01:31.199281 2548 slave.cpp:2227] Master disconnected! Waiting for > a new master to be elected > I0528 23:01:31.199578 2548 slave.cpp:2139] Status update manager > successfully handled status update TASK_RUNNING (UUID: > 08ed6d92-b404-4835-9fa8-85df7c809850) for task 0 of framework > 20140528-230130-16842879-56711-2525-0000 > I0528 23:01:31.199882 2548 slave.cpp:2145] Sending acknowledgement for > status update TASK_RUNNING (UUID: 08ed6d92-b404-4835-9fa8-85df7c809850) for > task 0 of framework 20140528-230130-16842879-56711-2525-0000 to > executor(1)@127.0.1.1:56711 > I0528 23:01:31.200449 2546 exec.cpp:338] Executor received status update > acknowledgement 08ed6d92-b404-4835-9fa8-85df7c809850 for task 0 of framework > 20140528-230130-16842879-56711-2525-0000 > I0528 23:01:31.200644 2548 slave.cpp:1604] Status update manager > successfully handled status update acknowledgement (UUID: > 08ed6d92-b404-4835-9fa8-85df7c809850) for task 0 of framework > 20140528-230130-16842879-56711-2525-0000 > I0528 23:01:31.201449 2551 group.cpp:711] Found non-sequence node > 'log_replicas' at '/znode' in ZooKeeper > I0528 23:01:31.201501 2551 detector.cpp:123] The current leader (id=0) is > lost > I0528 23:01:31.201513 2551 detector.cpp:135] Detected a new leader: None > I0528 23:01:31.201594 2551 slave.cpp:581] Lost leading master > I0528 23:01:31.201606 2551 slave.cpp:585] Detecting new master > I0528 23:01:31.202530 2545 group.cpp:711] Found non-sequence node > 'log_replicas' at '/znode' in ZooKeeper > I0528 23:01:31.202581 2545 detector.cpp:123] The current leader (id=0) is > lost > I0528 23:01:31.202592 2545 detector.cpp:135] Detected a new leader: None > I0528 23:01:31.202672 2545 sched.cpp:216] Scheduler::disconnected took 7248ns > I0528 23:01:31.202795 2545 sched.cpp:238] No master detected > I0528 23:02:31.141058 2547 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148755232129930days > I0528 23:03:31.141691 2551 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148755232129930days > I0528 23:04:31.141957 2551 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148755232129930days > I0528 23:05:31.142191 2551 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148755232129930days > I0528 23:06:31.143242 2551 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148755232129930days > I0528 23:07:31.143743 2551 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148755232129930days > I0528 23:08:31.145093 2551 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148755232129930days > I0528 23:09:31.145867 2551 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148755232129930days > I0528 23:10:31.146836 2551 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148755232129930days > I0528 23:11:31.147409 2551 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148755232129930days > I0528 23:12:31.148776 2551 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148755232129930days > I0528 23:13:31.149660 2551 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148755232129930days > I0528 23:14:31.150027 2551 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148755232129930days > I0528 23:15:31.150233 2551 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148755232129930days > I0528 23:16:31.151170 2551 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148755232129930days > I0528 23:17:31.151763 2548 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148755232129930days > I0528 23:18:31.152526 2548 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148755232129930days > I0528 23:19:31.153273 2548 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148755232129930days > I0528 23:20:31.154023 2546 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148755232129930days > I0528 23:21:31.155117 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148755232129930days > I0528 23:22:31.156105 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148755232129930days > I0528 23:23:31.157466 2547 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148755232129930days > I0528 23:24:31.158442 2547 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148755232129930days > I0528 23:25:31.159039 2548 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148755232129930days > I0528 23:26:31.159661 2551 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148755232129930days > I0528 23:27:31.159891 2545 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148755232129930days > I0528 23:28:31.160538 2545 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148755232129930days > I0528 23:29:31.161767 2548 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148755232129930days > I0528 23:30:31.162417 2551 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148755232129930days > I0528 23:31:31.165843 2546 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148755232129930days > I0528 23:32:31.170677 2550 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148755232129930days > I0528 23:33:31.171139 2547 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148755232129930days > I0528 23:34:31.172304 2548 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148755232129930days > I0528 23:35:31.173142 2548 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148755232129930days > I0528 23:36:31.173465 2548 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148755232129930days > I0528 23:37:31.174376 2548 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148755232129930days > I0528 23:38:31.174832 2548 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148755232129930days > I0528 23:39:31.175855 2548 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148755232129930days > I0528 23:40:31.176722 2548 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148755232129930days > I0528 23:41:31.177461 2548 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148755232129930days > I0528 23:42:31.178416 2548 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148755232129930days > I0528 23:43:31.178985 2548 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148755232129930days > I0528 23:44:31.179862 2548 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148755232129930days > I0528 23:45:31.180521 2548 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148755232129930days > I0528 23:46:31.181726 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148755232129930days > I0528 23:47:31.181965 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148755232129930days > I0528 23:48:31.183176 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148755232129930days > I0528 23:49:31.183990 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148755232129930days > I0528 23:50:31.184509 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148755232129930days > I0528 23:51:31.185294 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148755232129930days > I0528 23:52:31.186136 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148755232129930days > I0528 23:53:31.187158 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148755232129930days > I0528 23:54:31.187582 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0528 23:55:31.188880 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0528 23:56:31.189348 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0528 23:57:31.190219 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0528 23:58:31.191210 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0528 23:59:31.191658 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:00:31.192495 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:01:31.193559 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:02:31.194813 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:03:31.195615 2546 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:04:31.196190 2546 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:05:31.196672 2546 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:06:31.196949 2550 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:07:31.197409 2547 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:08:31.198567 2547 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:09:31.199897 2544 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:10:31.201149 2551 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:11:31.201594 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:12:31.202734 2545 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:13:31.203193 2546 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:14:31.203938 2548 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:15:31.212468 2551 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:16:31.213429 2551 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:17:31.214761 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:18:31.216003 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:19:31.217118 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:20:31.218351 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:21:31.219198 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:22:31.220232 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:23:31.220885 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:24:31.221834 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:25:31.223023 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:26:31.223954 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:27:31.225189 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:28:31.226090 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:29:31.226436 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:30:31.227349 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:31:31.227589 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:32:31.228602 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:33:31.228768 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:34:31.229239 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:35:31.229789 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:36:31.230901 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:37:31.231127 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:38:31.232071 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:39:31.232647 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:40:31.233716 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:41:31.234802 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:42:31.236125 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:43:31.238757 2551 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:44:31.240754 2550 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:45:31.241252 2550 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:46:31.242573 2550 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:47:31.243199 2546 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:48:31.243666 2544 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:49:31.244987 2547 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:50:31.245450 2546 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:51:31.245956 2546 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:52:31.246163 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:53:31.247390 2545 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:54:31.248394 2545 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:55:31.249528 2551 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:56:31.250185 2550 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:57:31.250687 2548 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:58:31.251855 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 00:59:31.252113 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 01:00:31.252485 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 01:01:31.252909 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 01:02:31.254098 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 01:03:31.255105 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 01:04:31.256420 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 01:05:31.257699 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 01:06:31.257926 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 01:07:31.258950 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 01:08:31.260201 2549 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 01:09:31.261404 2544 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 01:10:31.262702 2544 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 01:11:31.263573 2544 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 01:12:31.265055 2544 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 01:13:31.266525 2544 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 01:14:31.266850 2544 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 01:15:31.267858 2544 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > I0529 01:16:31.268621 2544 slave.cpp:2873] Current usage 45.02%. Max allowed > age: 3.148754323971123days > Build timed out (after 240 minutes). Marking the build as failed. > {noformat} -- This message was sent by Atlassian JIRA (v6.2#6252)