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 >> >
