Disabled the test for now until we home in on the problem:
commit 7a6d4e652ce6da41717231954f409baebdca6311
Author: Niklas Q. Nielsen <[email protected]>
Date: Wed Dec 17 13:24:43 2014 -0800
Temporarily disabled health check test.
Health check test is flaky and has been temporarily disabled until we
have found the root cause.
On 17 December 2014 at 09:33, Tim Chen <[email protected]> wrote:
>
> Hi Ben,
>
> Will be taking a look for sure, perhaps we should disable it for now.
>
> Tim
>
> On Wed, Dec 17, 2014 at 8:54 AM, Niklas Nielsen <[email protected]>
> wrote:
>>
>> Hi Ben,
>>
>> Sorry the tardy reply - just got back from our company off-site.
>> Will take a look with Tim - thanks for bringing this up.
>>
>> Niklas
>>
>> On 15 December 2014 at 19:08, Benjamin Mahler <[email protected]>
>> wrote:
>>>
>>> +tim, nik
>>>
>>> Looks like the health check test is still flaky, can you take a look? :)
>>>
>>> On Sun, Dec 14, 2014 at 12:56 PM, Apache Jenkins Server <
>>> [email protected]> wrote:
>>>>
>>>> See <
>>>> https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/2630/changes
>>>> >
>>>>
>>>> Changes:
>>>>
>>>> [dave] Adds Branding Brand to Mesos adopters list.
>>>>
>>>> ------------------------------------------
>>>> [...truncated 66646 lines...]
>>>>
>>>> [----------] 1 test from SchedulerTest
>>>> [ RUN ] SchedulerTest.TaskRunning
>>>> Using temporary directory '/tmp/SchedulerTest_TaskRunning_0UuLSy'
>>>> I1214 20:56:27.392043 11667 leveldb.cpp:176] Opened db in 2.763678ms
>>>> I1214 20:56:27.393041 11667 leveldb.cpp:183] Compacted db in 963138ns
>>>> I1214 20:56:27.393090 11667 leveldb.cpp:198] Created db iterator in
>>>> 19447ns
>>>> I1214 20:56:27.393110 11667 leveldb.cpp:204] Seeked to beginning of db
>>>> in 2017ns
>>>> I1214 20:56:27.393120 11667 leveldb.cpp:273] Iterated through 0 keys in
>>>> the db in 333ns
>>>> I1214 20:56:27.393156 11667 replica.cpp:741] Replica recovered with log
>>>> positions 0 -> 0 with 1 holes and 0 unlearned
>>>> I1214 20:56:27.393601 11694 recover.cpp:437] Starting replica recovery
>>>> I1214 20:56:27.393851 11694 recover.cpp:463] Replica is in EMPTY status
>>>> I1214 20:56:27.395179 11693 replica.cpp:638] Replica in EMPTY status
>>>> received a broadcasted recover request
>>>> I1214 20:56:27.395802 11695 recover.cpp:188] Received a recover
>>>> response from a replica in EMPTY status
>>>> I1214 20:56:27.396311 11690 recover.cpp:554] Updating replica status to
>>>> STARTING
>>>> I1214 20:56:27.397222 11689 leveldb.cpp:306] Persisting metadata (8
>>>> bytes) to leveldb took 605610ns
>>>> I1214 20:56:27.397255 11689 replica.cpp:320] Persisted replica status
>>>> to STARTING
>>>> I1214 20:56:27.397588 11686 recover.cpp:463] Replica is in STARTING
>>>> status
>>>> I1214 20:56:27.398885 11696 replica.cpp:638] Replica in STARTING status
>>>> received a broadcasted recover request
>>>> I1214 20:56:27.399435 11695 recover.cpp:188] Received a recover
>>>> response from a replica in STARTING status
>>>> I1214 20:56:27.400051 11692 recover.cpp:554] Updating replica status to
>>>> VOTING
>>>> I1214 20:56:27.400722 11684 leveldb.cpp:306] Persisting metadata (8
>>>> bytes) to leveldb took 372808ns
>>>> I1214 20:56:27.400748 11684 replica.cpp:320] Persisted replica status
>>>> to VOTING
>>>> I1214 20:56:27.400833 11689 recover.cpp:568] Successfully joined the
>>>> Paxos group
>>>> I1214 20:56:27.409098 11695 master.cpp:258] Master
>>>> 20141214-205627-3142697795-57086-11667 (pomona.apache.org) started on
>>>> 67.195.81.187:57086
>>>> I1214 20:56:27.515343 11695 master.cpp:304] Master only allowing
>>>> authenticated frameworks to register
>>>> I1214 20:56:27.515364 11695 master.cpp:309] Master only allowing
>>>> authenticated slaves to register
>>>> I1214 20:56:27.515390 11695 credentials.hpp:36] Loading credentials for
>>>> authentication from '/tmp/SchedulerTest_TaskRunning_0UuLSy/credentials'
>>>> I1214 20:56:27.515445 11689 recover.cpp:452] Recover process terminated
>>>> I1214 20:56:27.515666 11695 master.cpp:353] Authorization enabled
>>>> I1214 20:56:27.516333 11685 whitelist_watcher.cpp:61] No whitelist given
>>>> I1214 20:56:27.516384 11689 hierarchical_allocator_process.hpp:280]
>>>> Initialized hierarchical allocator process
>>>> I1214 20:56:27.516517 11689 hierarchical_allocator_process.hpp:527]
>>>> Advertising offers for all slaves
>>>> I1214 20:56:27.517618 11693 master.cpp:1213] The newly elected leader
>>>> is [email protected]:57086 with id
>>>> 20141214-205627-3142697795-57086-11667
>>>> I1214 20:56:27.517652 11693 master.cpp:1226] Elected as the leading
>>>> master!
>>>> I1214 20:56:27.517669 11693 master.cpp:1044] Recovering from registrar
>>>> I1214 20:56:27.517856 11690 registrar.cpp:313] Recovering registrar
>>>> I1214 20:56:27.518504 11693 log.cpp:656] Attempting to start the writer
>>>> I1214 20:56:27.520063 11681 replica.cpp:474] Replica received implicit
>>>> promise request with proposal 1
>>>> I1214 20:56:27.520660 11681 leveldb.cpp:306] Persisting metadata (8
>>>> bytes) to leveldb took 562289ns
>>>> I1214 20:56:27.520678 11681 replica.cpp:342] Persisted promised to 1
>>>> I1214 20:56:27.521118 11681 coordinator.cpp:230] Coordinator attemping
>>>> to fill missing position
>>>> I1214 20:56:27.522521 11696 replica.cpp:375] Replica received explicit
>>>> promise request for position 0 with proposal 2
>>>> I1214 20:56:27.523118 11696 leveldb.cpp:343] Persisting action (8
>>>> bytes) to leveldb took 556655ns
>>>> I1214 20:56:27.523145 11696 replica.cpp:676] Persisted action at 0
>>>> I1214 20:56:27.524786 11688 replica.cpp:508] Replica received write
>>>> request for position 0
>>>> I1214 20:56:27.524847 11688 leveldb.cpp:438] Reading position from
>>>> leveldb took 31799ns
>>>> I1214 20:56:27.525352 11688 leveldb.cpp:343] Persisting action (14
>>>> bytes) to leveldb took 470745ns
>>>> I1214 20:56:27.525377 11688 replica.cpp:676] Persisted action at 0
>>>> I1214 20:56:27.525954 11681 replica.cpp:655] Replica received learned
>>>> notice for position 0
>>>> I1214 20:56:27.526526 11681 leveldb.cpp:343] Persisting action (16
>>>> bytes) to leveldb took 549029ns
>>>> I1214 20:56:27.526548 11681 replica.cpp:676] Persisted action at 0
>>>> I1214 20:56:27.526568 11681 replica.cpp:661] Replica learned NOP action
>>>> at position 0
>>>> I1214 20:56:27.527350 11688 log.cpp:672] Writer started with ending
>>>> position 0
>>>> I1214 20:56:27.528616 11695 leveldb.cpp:438] Reading position from
>>>> leveldb took 24309ns
>>>> I1214 20:56:27.530694 11694 registrar.cpp:346] Successfully fetched the
>>>> registry (0B) in 12.784896ms
>>>> I1214 20:56:27.530822 11694 registrar.cpp:445] Applied 1 operations in
>>>> 27636ns; attempting to update the 'registry'
>>>> I1214 20:56:27.533664 11682 log.cpp:680] Attempting to append 139 bytes
>>>> to the log
>>>> I1214 20:56:27.533810 11690 coordinator.cpp:340] Coordinator attempting
>>>> to write APPEND action at position 1
>>>> I1214 20:56:27.534579 11694 replica.cpp:508] Replica received write
>>>> request for position 1
>>>> I1214 20:56:27.535003 11694 leveldb.cpp:343] Persisting action (158
>>>> bytes) to leveldb took 390753ns
>>>> I1214 20:56:27.535029 11694 replica.cpp:676] Persisted action at 1
>>>> I1214 20:56:27.535671 11683 replica.cpp:655] Replica received learned
>>>> notice for position 1
>>>> I1214 20:56:27.536224 11683 leveldb.cpp:343] Persisting action (160
>>>> bytes) to leveldb took 521277ns
>>>> I1214 20:56:27.536253 11683 replica.cpp:676] Persisted action at 1
>>>> I1214 20:56:27.536303 11683 replica.cpp:661] Replica learned APPEND
>>>> action at position 1
>>>> I1214 20:56:27.536975 11689 registrar.cpp:490] Successfully updated the
>>>> 'registry' in 6.095872ms
>>>> I1214 20:56:27.537116 11689 registrar.cpp:376] Successfully recovered
>>>> registrar
>>>> I1214 20:56:27.537211 11685 log.cpp:699] Attempting to truncate the log
>>>> to 1
>>>> I1214 20:56:27.537384 11688 coordinator.cpp:340] Coordinator attempting
>>>> to write TRUNCATE action at position 2
>>>> I1214 20:56:27.537408 11693 master.cpp:1071] Recovered 0 slaves from
>>>> the Registry (101B) ; allowing 10mins for slaves to re-register
>>>> I1214 20:56:27.538265 11695 replica.cpp:508] Replica received write
>>>> request for position 2
>>>> I1214 20:56:27.538646 11695 leveldb.cpp:343] Persisting action (16
>>>> bytes) to leveldb took 342709ns
>>>> I1214 20:56:27.538666 11695 replica.cpp:676] Persisted action at 2
>>>> I1214 20:56:27.539341 11689 replica.cpp:655] Replica received learned
>>>> notice for position 2
>>>> I1214 20:56:27.539798 11689 leveldb.cpp:343] Persisting action (18
>>>> bytes) to leveldb took 433843ns
>>>> I1214 20:56:27.539839 11689 leveldb.cpp:401] Deleting ~1 keys from
>>>> leveldb took 23311ns
>>>> I1214 20:56:27.539852 11689 replica.cpp:676] Persisted action at 2
>>>> I1214 20:56:27.539867 11689 replica.cpp:661] Replica learned TRUNCATE
>>>> action at position 2
>>>> I1214 20:56:27.556141 11686 slave.cpp:170] Slave started on 217)@
>>>> 67.195.81.187:57086
>>>> I1214 20:56:27.556180 11686 credentials.hpp:84] Loading credential for
>>>> authentication from '/tmp/SchedulerTest_TaskRunning_hLuzvx/credential'
>>>> I1214 20:56:27.556391 11686 slave.cpp:279] Slave using credential for:
>>>> test-principal
>>>> I1214 20:56:27.556648 11686 slave.cpp:297] Slave resources: cpus(*):2;
>>>> mem(*):1024; disk(*):1024; ports(*):[31000-32000]
>>>> I1214 20:56:27.556761 11686 slave.cpp:326] Slave hostname:
>>>> pomona.apache.org
>>>> I1214 20:56:27.556779 11686 slave.cpp:327] Slave checkpoint: false
>>>> W1214 20:56:27.556789 11686 slave.cpp:329] Disabling checkpointing is
>>>> deprecated and the --checkpoint flag will be removed in a future release.
>>>> Please avoid using this flag
>>>> I1214 20:56:27.557198 11667 scheduler.cpp:146] Version: 0.22.0
>>>> I1214 20:56:27.557570 11682 state.cpp:33] Recovering state from
>>>> '/tmp/SchedulerTest_TaskRunning_hLuzvx/meta'
>>>> I1214 20:56:27.557864 11685 status_update_manager.cpp:197] Recovering
>>>> status update manager
>>>> I1214 20:56:27.558148 11690 slave.cpp:3485] Finished recovery
>>>> I1214 20:56:27.558650 11685 slave.cpp:610] New master detected at
>>>> [email protected]:57086
>>>> I1214 20:56:27.558677 11695 status_update_manager.cpp:171] Pausing
>>>> sending status updates
>>>> I1214 20:56:27.558756 11685 slave.cpp:673] Authenticating with master
>>>> [email protected]:57086
>>>> I1214 20:56:27.558779 11685 slave.cpp:678] Using default CRAM-MD5
>>>> authenticatee
>>>> I1214 20:56:27.558925 11685 slave.cpp:646] Detecting new master
>>>> I1214 20:56:27.559078 11686 authenticatee.hpp:138] Creating new client
>>>> SASL connection
>>>> I1214 20:56:27.559273 11685 master.cpp:3920] Authenticating slave(217)@
>>>> 67.195.81.187:57086
>>>> I1214 20:56:27.559320 11685 master.cpp:3931] Using default CRAM-MD5
>>>> authenticator
>>>> I1214 20:56:27.559617 11683 authenticator.hpp:170] Creating new server
>>>> SASL connection
>>>> I1214 20:56:27.559885 11695 authenticatee.hpp:229] Received SASL
>>>> authentication mechanisms: CRAM-MD5
>>>> I1214 20:56:27.559922 11695 authenticatee.hpp:255] Attempting to
>>>> authenticate with mechanism 'CRAM-MD5'
>>>> I1214 20:56:27.560040 11681 authenticator.hpp:276] Received SASL
>>>> authentication start
>>>> I1214 20:56:27.560088 11694 scheduler.cpp:415] New master detected at
>>>> [email protected]:57086
>>>> I1214 20:56:27.560104 11681 authenticator.hpp:398] Authentication
>>>> requires more steps
>>>> I1214 20:56:27.560120 11694 scheduler.cpp:464] Authenticating with
>>>> master [email protected]:57086
>>>> I1214 20:56:27.560227 11691 authenticatee.hpp:275] Received SASL
>>>> authentication step
>>>> I1214 20:56:27.560407 11682 authenticator.hpp:304] Received SASL
>>>> authentication step
>>>> I1214 20:56:27.560442 11682 auxprop.cpp:99] Request to lookup
>>>> properties for user: 'test-principal' realm: 'pomona.apache.org'
>>>> server FQDN: 'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH:
>>>> false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
>>>> I1214 20:56:27.560456 11682 auxprop.cpp:171] Looking up auxiliary
>>>> property '*userPassword'
>>>> I1214 20:56:27.560503 11682 auxprop.cpp:171] Looking up auxiliary
>>>> property '*cmusaslsecretCRAM-MD5'
>>>> I1214 20:56:27.560611 11687 authenticatee.hpp:138] Creating new client
>>>> SASL connection
>>>> I1214 20:56:27.677618 11682 auxprop.cpp:99] Request to lookup
>>>> properties for user: 'test-principal' realm: 'pomona.apache.org'
>>>> server FQDN: 'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH:
>>>> false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
>>>> I1214 20:56:27.677642 11682 auxprop.cpp:121] Skipping auxiliary
>>>> property '*userPassword' since SASL_AUXPROP_AUTHZID == true
>>>> I1214 20:56:27.677650 11682 auxprop.cpp:121] Skipping auxiliary
>>>> property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
>>>> I1214 20:56:27.677673 11682 authenticator.hpp:390] Authentication
>>>> success
>>>> I1214 20:56:27.677825 11684 authenticatee.hpp:315] Authentication
>>>> success
>>>> I1214 20:56:27.677839 11687 master.cpp:3920] Authenticating
>>>> scheduler(1)@67.195.81.187:57086
>>>> I1214 20:56:27.677868 11687 master.cpp:3931] Using default CRAM-MD5
>>>> authenticator
>>>> I1214 20:56:27.678120 11684 slave.cpp:744] Successfully authenticated
>>>> with master [email protected]:57086
>>>> I1214 20:56:27.678262 11684 slave.cpp:1072] Will retry registration in
>>>> 9.672723ms if necessary
>>>> I1214 20:56:27.678308 11687 master.cpp:3978] Successfully authenticated
>>>> principal 'test-principal' at slave(217)@67.195.81.187:57086
>>>> I1214 20:56:27.678490 11682 authenticator.hpp:170] Creating new server
>>>> SASL connection
>>>> I1214 20:56:27.678678 11687 master.cpp:3078] Registering slave at
>>>> slave(217)@67.195.81.187:57086 (pomona.apache.org) with id
>>>> 20141214-205627-3142697795-57086-11667-S0
>>>> I1214 20:56:27.678701 11694 authenticatee.hpp:229] Received SASL
>>>> authentication mechanisms: CRAM-MD5
>>>> I1214 20:56:27.678725 11694 authenticatee.hpp:255] Attempting to
>>>> authenticate with mechanism 'CRAM-MD5'
>>>> I1214 20:56:27.678788 11694 authenticator.hpp:276] Received SASL
>>>> authentication start
>>>> I1214 20:56:27.678824 11694 authenticator.hpp:398] Authentication
>>>> requires more steps
>>>> I1214 20:56:27.678915 11693 authenticatee.hpp:275] Received SASL
>>>> authentication step
>>>> I1214 20:56:27.679023 11689 authenticator.hpp:304] Received SASL
>>>> authentication step
>>>> I1214 20:56:27.679049 11689 auxprop.cpp:99] Request to lookup
>>>> properties for user: 'test-principal' realm: 'pomona.apache.org'
>>>> server FQDN: 'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH:
>>>> false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
>>>> I1214 20:56:27.679059 11689 auxprop.cpp:171] Looking up auxiliary
>>>> property '*userPassword'
>>>> I1214 20:56:27.679092 11689 auxprop.cpp:171] Looking up auxiliary
>>>> property '*cmusaslsecretCRAM-MD5'
>>>> I1214 20:56:27.679116 11689 auxprop.cpp:99] Request to lookup
>>>> properties for user: 'test-principal' realm: 'pomona.apache.org'
>>>> server FQDN: 'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH:
>>>> false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
>>>> I1214 20:56:27.679126 11689 auxprop.cpp:121] Skipping auxiliary
>>>> property '*userPassword' since SASL_AUXPROP_AUTHZID == true
>>>> I1214 20:56:27.679131 11689 auxprop.cpp:121] Skipping auxiliary
>>>> property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
>>>> I1214 20:56:27.679144 11689 authenticator.hpp:390] Authentication
>>>> success
>>>> I1214 20:56:27.679147 11688 registrar.cpp:445] Applied 1 operations in
>>>> 87582ns; attempting to update the 'registry'
>>>> I1214 20:56:27.679257 11689 authenticatee.hpp:315] Authentication
>>>> success
>>>> I1214 20:56:27.679296 11692 master.cpp:3978] Successfully authenticated
>>>> principal 'test-principal' at scheduler(1)@67.195.81.187:57086
>>>> I1214 20:56:27.679663 11687 scheduler.cpp:535] Successfully
>>>> authenticated with master [email protected]:57086
>>>> I1214 20:56:27.681074 11692 master.cpp:1333] Received registration
>>>> request for framework 'default' at scheduler(1)@67.195.81.187:57086
>>>> I1214 20:56:27.681149 11692 master.cpp:1292] Authorizing framework
>>>> principal 'test-principal' to receive offers for role '*'
>>>> I1214 20:56:27.681773 11690 master.cpp:1397] Registering framework
>>>> 20141214-205627-3142697795-57086-11667-0000 (default) at scheduler(1)@
>>>> 67.195.81.187:57086
>>>> I1214 20:56:27.682173 11694 hierarchical_allocator_process.hpp:314]
>>>> Added framework 20141214-205627-3142697795-57086-11667-0000
>>>> I1214 20:56:27.682210 11694 hierarchical_allocator_process.hpp:767] No
>>>> resources available to allocate!
>>>> I1214 20:56:27.682222 11694 hierarchical_allocator_process.hpp:674]
>>>> Performed allocation for 0 slaves in 21647ns
>>>> I1214 20:56:27.682718 11684 log.cpp:680] Attempting to append 316 bytes
>>>> to the log
>>>> I1214 20:56:27.682785 11689 scheduler.cpp:584] Enqueuing event 1 from
>>>> [email protected]:57086
>>>> I1214 20:56:27.682839 11687 coordinator.cpp:340] Coordinator attempting
>>>> to write APPEND action at position 3
>>>> I1214 20:56:27.683965 11693 replica.cpp:508] Replica received write
>>>> request for position 3
>>>> I1214 20:56:27.684310 11693 leveldb.cpp:343] Persisting action (335
>>>> bytes) to leveldb took 304957ns
>>>> I1214 20:56:27.684340 11693 replica.cpp:676] Persisted action at 3
>>>> I1214 20:56:27.684962 11688 replica.cpp:655] Replica received learned
>>>> notice for position 3
>>>> I1214 20:56:27.685477 11688 leveldb.cpp:343] Persisting action (337
>>>> bytes) to leveldb took 487772ns
>>>> I1214 20:56:27.685508 11688 replica.cpp:676] Persisted action at 3
>>>> I1214 20:56:27.685534 11688 replica.cpp:661] Replica learned APPEND
>>>> action at position 3
>>>> I1214 20:56:27.686558 11696 registrar.cpp:490] Successfully updated the
>>>> 'registry' in 7.350016ms
>>>> I1214 20:56:27.686732 11692 log.cpp:699] Attempting to truncate the log
>>>> to 3
>>>> I1214 20:56:27.686844 11695 coordinator.cpp:340] Coordinator attempting
>>>> to write TRUNCATE action at position 4
>>>> I1214 20:56:27.687173 11689 slave.cpp:2556] Received ping from
>>>> slave-observer(198)@67.195.81.187:57086
>>>> I1214 20:56:27.687218 11693 master.cpp:3132] Registered slave
>>>> 20141214-205627-3142697795-57086-11667-S0 at slave(217)@
>>>> 67.195.81.187:57086 (pomona.apache.org) with cpus(*):2; mem(*):1024;
>>>> disk(*):1024; ports(*):[31000-32000]
>>>> I1214 20:56:27.687357 11689 slave.cpp:778] Registered with master
>>>> [email protected]:57086; given slave ID
>>>> 20141214-205627-3142697795-57086-11667-S0
>>>> I1214 20:56:27.687386 11686 hierarchical_allocator_process.hpp:448]
>>>> Added slave 20141214-205627-3142697795-57086-11667-S0 (
>>>> pomona.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024;
>>>> ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):1024;
>>>> ports(*):[31000-32000] available)
>>>> I1214 20:56:27.687531 11681 status_update_manager.cpp:178] Resuming
>>>> sending status updates
>>>> I1214 20:56:27.687615 11696 replica.cpp:508] Replica received write
>>>> request for position 4
>>>> I1214 20:56:27.687806 11686 hierarchical_allocator_process.hpp:692]
>>>> Performed allocation for slave 20141214-205627-3142697795-57086-11667-S0 in
>>>> 368138ns
>>>> I1214 20:56:27.687978 11696 leveldb.cpp:343] Persisting action (16
>>>> bytes) to leveldb took 330651ns
>>>> I1214 20:56:27.688011 11696 replica.cpp:676] Persisted action at 4
>>>> I1214 20:56:27.688154 11686 master.cpp:3862] Sending 1 offers to
>>>> framework 20141214-205627-3142697795-57086-11667-0000 (default) at
>>>> scheduler(1)@67.195.81.187:57086
>>>> I1214 20:56:27.688673 11684 scheduler.cpp:584] Enqueuing event 3 from
>>>> [email protected]:57086
>>>> I1214 20:56:27.688781 11681 replica.cpp:655] Replica received learned
>>>> notice for position 4
>>>> I1214 20:56:27.689249 11681 leveldb.cpp:343] Persisting action (18
>>>> bytes) to leveldb took 413097ns
>>>> I1214 20:56:27.689344 11681 leveldb.cpp:401] Deleting ~2 keys from
>>>> leveldb took 68413ns
>>>> I1214 20:56:27.689368 11681 replica.cpp:676] Persisted action at 4
>>>> I1214 20:56:27.689395 11681 replica.cpp:661] Replica learned TRUNCATE
>>>> action at position 4
>>>> I1214 20:56:27.691339 11684 master.cpp:2401] Processing reply for
>>>> offers: [ 20141214-205627-3142697795-57086-11667-O0 ] on slave
>>>> 20141214-205627-3142697795-57086-11667-S0 at slave(217)@
>>>> 67.195.81.187:57086 (pomona.apache.org) for framework
>>>> 20141214-205627-3142697795-57086-11667-0000 (default) at scheduler(1)@
>>>> 67.195.81.187:57086
>>>> I1214 20:56:27.691376 11684 master.cpp:2507] Authorizing framework
>>>> principal 'test-principal' to launch task 1 as user 'jenkins'
>>>> W1214 20:56:27.692301 11696 master.cpp:2034] Executor default for task
>>>> 1 uses less CPUs (None) than the minimum required (0.01). Please update
>>>> your executor, as this will be mandatory in future releases.
>>>> W1214 20:56:27.835728 11696 master.cpp:2046] Executor default for task
>>>> 1 uses less memory (None) than the minimum required (32MB). Please update
>>>> your executor, as this will be mandatory in future releases.
>>>> I1214 20:56:27.836158 11696 master.hpp:758] Adding task 1 with
>>>> resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on
>>>> slave 20141214-205627-3142697795-57086-11667-S0 (pomona.apache.org)
>>>> I1214 20:56:27.836266 11696 master.cpp:2706] Launching task 1 of
>>>> framework 20141214-205627-3142697795-57086-11667-0000 (default) at
>>>> scheduler(1)@67.195.81.187:57086 with resources cpus(*):2;
>>>> mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
>>>> 20141214-205627-3142697795-57086-11667-S0 at slave(217)@
>>>> 67.195.81.187:57086 (pomona.apache.org)
>>>> I1214 20:56:27.836807 11683 slave.cpp:1103] Got assigned task 1 for
>>>> framework 20141214-205627-3142697795-57086-11667-0000
>>>> I1214 20:56:27.837564 11683 slave.cpp:1213] Launching task 1 for
>>>> framework 20141214-205627-3142697795-57086-11667-0000
>>>> I1214 20:56:27.840258 11683 slave.cpp:3867] Launching executor default
>>>> of framework 20141214-205627-3142697795-57086-11667-0000 in work directory
>>>> '/tmp/SchedulerTest_TaskRunning_hLuzvx/slaves/20141214-205627-3142697795-57086-11667-S0/frameworks/20141214-205627-3142697795-57086-11667-0000/executors/default/runs/35d13ad6-716e-4800-a05e-10d12fd934d2'
>>>> I1214 20:56:27.843242 11683 exec.cpp:132] Version: 0.22.0
>>>> I1214 20:56:27.843632 11692 exec.cpp:182] Executor started at:
>>>> executor(76)@67.195.81.187:57086 with pid 11667
>>>> I1214 20:56:27.843744 11683 slave.cpp:1336] Queuing task '1' for
>>>> executor default of framework '20141214-205627-3142697795-57086-11667-0000
>>>> I1214 20:56:27.843879 11683 slave.cpp:563] Successfully attached file
>>>> '/tmp/SchedulerTest_TaskRunning_hLuzvx/slaves/20141214-205627-3142697795-57086-11667-S0/frameworks/20141214-205627-3142697795-57086-11667-0000/executors/default/runs/35d13ad6-716e-4800-a05e-10d12fd934d2'
>>>> I1214 20:56:27.844007 11683 slave.cpp:2858] Monitoring executor
>>>> 'default' of framework '20141214-205627-3142697795-57086-11667-0000' in
>>>> container '35d13ad6-716e-4800-a05e-10d12fd934d2'
>>>> I1214 20:56:27.844187 11683 slave.cpp:1880] Got registration for
>>>> executor 'default' of framework 20141214-205627-3142697795-57086-11667-0000
>>>> from executor(76)@67.195.81.187:57086
>>>> I1214 20:56:27.844635 11683 slave.cpp:1999] Flushing queued task 1 for
>>>> executor 'default' of framework 20141214-205627-3142697795-57086-11667-0000
>>>> I1214 20:56:27.844759 11682 exec.cpp:206] Executor registered on slave
>>>> 20141214-205627-3142697795-57086-11667-S0
>>>> I1214 20:56:27.846896 11682 exec.cpp:218] Executor::registered took
>>>> 26412ns
>>>> I1214 20:56:27.847084 11682 exec.cpp:293] Executor asked to run task '1'
>>>> I1214 20:56:27.847165 11682 exec.cpp:302] Executor::launchTask took
>>>> 59819ns
>>>> I1214 20:56:27.849412 11682 exec.cpp:525] Executor sending status
>>>> update TASK_RUNNING (UUID: b1b5d161-1c8c-46e4-8744-81d3bd434147) for task 1
>>>> of framework 20141214-205627-3142697795-57086-11667-0000
>>>> I1214 20:56:27.849660 11682 slave.cpp:2233] Handling status update
>>>> TASK_RUNNING (UUID: b1b5d161-1c8c-46e4-8744-81d3bd434147) for task 1 of
>>>> framework 20141214-205627-3142697795-57086-11667-0000 from executor(76)@
>>>> 67.195.81.187:57086
>>>> I1214 20:56:27.849942 11691 status_update_manager.cpp:317] Received
>>>> status update TASK_RUNNING (UUID: b1b5d161-1c8c-46e4-8744-81d3bd434147) for
>>>> task 1 of framework 20141214-205627-3142697795-57086-11667-0000
>>>> I1214 20:56:27.849999 11691 status_update_manager.cpp:494] Creating
>>>> StatusUpdate stream for task 1 of framework
>>>> 20141214-205627-3142697795-57086-11667-0000
>>>> I1214 20:56:27.850219 11691 status_update_manager.cpp:371] Forwarding
>>>> update TASK_RUNNING (UUID: b1b5d161-1c8c-46e4-8744-81d3bd434147) for task 1
>>>> of framework 20141214-205627-3142697795-57086-11667-0000 to the slave
>>>> I1214 20:56:27.850538 11682 slave.cpp:2476] Forwarding the update
>>>> TASK_RUNNING (UUID: b1b5d161-1c8c-46e4-8744-81d3bd434147) for task 1 of
>>>> framework 20141214-205627-3142697795-57086-11667-0000 to
>>>> [email protected]:57086
>>>> I1214 20:56:27.850862 11682 slave.cpp:2403] Status update manager
>>>> successfully handled status update TASK_RUNNING (UUID:
>>>> b1b5d161-1c8c-46e4-8744-81d3bd434147) for task 1 of framework
>>>> 20141214-205627-3142697795-57086-11667-0000
>>>> I1214 20:56:27.850893 11682 slave.cpp:2409] Sending acknowledgement for
>>>> status update TASK_RUNNING (UUID: b1b5d161-1c8c-46e4-8744-81d3bd434147) for
>>>> task 1 of framework 20141214-205627-3142697795-57086-11667-0000 to
>>>> executor(76)@67.195.81.187:57086
>>>> I1214 20:56:27.850957 11688 master.cpp:3455] Forwarding status update
>>>> TASK_RUNNING (UUID: b1b5d161-1c8c-46e4-8744-81d3bd434147) for task 1 of
>>>> framework 20141214-205627-3142697795-57086-11667-0000
>>>> I1214 20:56:27.851085 11690 exec.cpp:339] Executor received status
>>>> update acknowledgement b1b5d161-1c8c-46e4-8744-81d3bd434147 for task 1 of
>>>> framework 20141214-205627-3142697795-57086-11667-0000
>>>> I1214 20:56:27.851110 11688 master.cpp:3427] Status update TASK_RUNNING
>>>> (UUID: b1b5d161-1c8c-46e4-8744-81d3bd434147) for task 1 of framework
>>>> 20141214-205627-3142697795-57086-11667-0000 from slave
>>>> 20141214-205627-3142697795-57086-11667-S0 at slave(217)@
>>>> 67.195.81.187:57086 (pomona.apache.org)
>>>> I1214 20:56:27.851167 11688 master.cpp:4725] Updating the latest state
>>>> of task 1 of framework 20141214-205627-3142697795-57086-11667-0000 to
>>>> TASK_RUNNING
>>>> I1214 20:56:27.851228 11687 scheduler.cpp:584] Enqueuing event 5 from
>>>> [email protected]:57086
>>>> I1214 20:56:27.852569 11667 master.cpp:648] Master terminating
>>>> W1214 20:56:27.852744 11667 master.cpp:4770] Removing task 1 with
>>>> resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] of
>>>> framework 20141214-205627-3142697795-57086-11667-0000 on slave
>>>> 20141214-205627-3142697795-57086-11667-S0 at slave(217)@
>>>> 67.195.81.187:57086 (pomona.apache.org) in non-terminal state
>>>> TASK_RUNNING
>>>> I1214 20:56:27.853072 11695 hierarchical_allocator_process.hpp:581]
>>>> Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
>>>> (total allocatable: cpus(*):2; mem(*):1024; disk(*):1024;
>>>> ports(*):[31000-32000]) on slave 20141214-205627-3142697795-57086-11667-S0
>>>> from framework 20141214-205627-3142697795-57086-11667-0000
>>>> I1214 20:56:27.853247 11667 master.cpp:4813] Removing executor
>>>> 'default' with resources of framework
>>>> 20141214-205627-3142697795-57086-11667-0000 on slave
>>>> 20141214-205627-3142697795-57086-11667-S0 at slave(217)@
>>>> 67.195.81.187:57086 (pomona.apache.org)
>>>> I1214 20:56:27.854033 11696 slave.cpp:2641] [email protected]:57086
>>>> exited
>>>> W1214 20:56:27.854066 11696 slave.cpp:2644] Master disconnected!
>>>> Waiting for a new master to be elected
>>>> I1214 20:56:27.865756 11688 slave.cpp:2916] Executor 'default' of
>>>> framework 20141214-205627-3142697795-57086-11667-0000 exited with status 0
>>>> I1214 20:56:27.867316 11688 slave.cpp:2233] Handling status update
>>>> TASK_LOST (UUID: df99716d-67aa-4acf-a919-95c1a5e51f3f) for task 1 of
>>>> framework 20141214-205627-3142697795-57086-11667-0000 from @0.0.0.0:0
>>>> I1214 20:56:27.867383 11688 slave.cpp:4175] Terminating task 1
>>>> I1214 20:56:27.867626 11688 slave.cpp:492] Slave terminating
>>>> I1214 20:56:27.867702 11688 slave.cpp:1553] Asked to shut down
>>>> framework 20141214-205627-3142697795-57086-11667-0000 by @0.0.0.0:0
>>>> I1214 20:56:27.867720 11688 slave.cpp:1578] Shutting down framework
>>>> 20141214-205627-3142697795-57086-11667-0000
>>>> I1214 20:56:27.867782 11688 slave.cpp:3025] Cleaning up executor
>>>> 'default' of framework 20141214-205627-3142697795-57086-11667-0000
>>>> I1214 20:56:27.867924 11695 gc.cpp:56] Scheduling
>>>> '/tmp/SchedulerTest_TaskRunning_hLuzvx/slaves/20141214-205627-3142697795-57086-11667-S0/frameworks/20141214-205627-3142697795-57086-11667-0000/executors/default/runs/35d13ad6-716e-4800-a05e-10d12fd934d2'
>>>> for gc 6.99998995548741days in the future
>>>> I1214 20:56:27.868001 11688 slave.cpp:3102] Cleaning up framework
>>>> 20141214-205627-3142697795-57086-11667-0000
>>>> I1214 20:56:27.868098 11695 gc.cpp:56] Scheduling
>>>> '/tmp/SchedulerTest_TaskRunning_hLuzvx/slaves/20141214-205627-3142697795-57086-11667-S0/frameworks/20141214-205627-3142697795-57086-11667-0000/executors/default'
>>>> for gc 6.99998995423704days in the future
>>>> I1214 20:56:27.868113 11684 status_update_manager.cpp:279] Closing
>>>> status update streams for framework
>>>> 20141214-205627-3142697795-57086-11667-0000
>>>> I1214 20:56:27.995924 11684 status_update_manager.cpp:525] Cleaning up
>>>> status update stream for task 1 of framework
>>>> 20141214-205627-3142697795-57086-11667-0000
>>>> [ OK ] SchedulerTest.TaskRunning (610 ms)
>>>> [----------] 1 test from SchedulerTest (610 ms total)
>>>>
>>>> [----------] Global test environment tear-down
>>>> [==========] 452 tests from 69 test cases ran. (113108 ms total)
>>>> [ PASSED ] 451 tests.
>>>> [ FAILED ] 1 test, listed below:
>>>> [ FAILED ] HealthCheckTest.GracePeriod
>>>>
>>>> 1 FAILED TEST
>>>> YOU HAVE 4 DISABLED TESTS
>>>>
>>>> make[3]: *** [check-local] Error 1
>>>> make[3]: Leaving directory `<
>>>> https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/ws/build/src
>>>> '>
>>>> make[2]: *** [check-am] Error 2
>>>> make[2]: Leaving directory `<
>>>> https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/ws/build/src
>>>> '>
>>>> make[1]: *** [check] Error 2
>>>> make[1]: Leaving directory `<
>>>> https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/ws/build/src
>>>> '>
>>>> make: *** [check-recursive] Error 1
>>>> Test finished
>>>> Exit status: 2
>>>> Build step 'Execute shell' marked build as failure
>>>> Recording test results
>>>>
>>>
