You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@mesos.apache.org by "Dominic Hamon (JIRA)" <ji...@apache.org> on 2014/06/16 19:48:03 UTC
[jira] [Resolved] (MESOS-1436)
AllocatorZooKeeperTest/0.SlaveReregistersFirst flaky and can run forever
[ 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)