See <https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/2373/changes>
Changes: [bmahler] Fixed the flaky FaultToleranceTest.ReconcilePendingTasks. ------------------------------------------ [...truncated 31684 lines...] I0913 07:19:54.157225 5755 replica.cpp:638] Replica in STARTING status received a broadcasted recover request I0913 07:19:54.157299 5755 recover.cpp:188] Received a recover response from a replica in STARTING status I0913 07:19:54.157402 5755 recover.cpp:542] Updating replica status to VOTING I0913 07:19:54.157693 5755 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 238277ns I0913 07:19:54.157711 5755 replica.cpp:320] Persisted replica status to VOTING I0913 07:19:54.157752 5755 recover.cpp:556] Successfully joined the Paxos group I0913 07:19:54.157805 5755 recover.cpp:440] Recover process terminated I0913 07:19:54.157912 5755 log.cpp:656] Attempting to start the writer I0913 07:19:54.158201 5755 replica.cpp:474] Replica received implicit promise request with proposal 1 I0913 07:19:54.158321 5755 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 102959ns I0913 07:19:54.158336 5755 replica.cpp:342] Persisted promised to 1 I0913 07:19:54.158509 5755 coordinator.cpp:230] Coordinator attemping to fill missing position I0913 07:19:54.158836 5755 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2 I0913 07:19:54.158965 5755 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 110359ns I0913 07:19:54.158982 5755 replica.cpp:676] Persisted action at 0 I0913 07:19:54.159245 5755 replica.cpp:508] Replica received write request for position 0 I0913 07:19:54.159271 5755 leveldb.cpp:438] Reading position from leveldb took 11152ns I0913 07:19:54.159390 5755 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 102629ns I0913 07:19:54.159405 5755 replica.cpp:676] Persisted action at 0 I0913 07:19:54.159548 5755 replica.cpp:655] Replica received learned notice for position 0 I0913 07:19:54.159742 5755 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 177450ns I0913 07:19:54.159759 5755 replica.cpp:676] Persisted action at 0 I0913 07:19:54.159768 5755 replica.cpp:661] Replica learned NOP action at position 0 I0913 07:19:54.160043 5765 log.cpp:672] Writer started with ending position 0 I0913 07:19:54.160296 5765 leveldb.cpp:438] Reading position from leveldb took 9415ns I0913 07:19:54.161617 5765 registrar.cpp:346] Successfully fetched the registry (0B) I0913 07:19:54.161639 5765 registrar.cpp:422] Attempting to update the 'registry' I0913 07:19:54.163061 5765 log.cpp:680] Attempting to append 138 bytes to the log I0913 07:19:54.163106 5765 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1 I0913 07:19:54.163308 5765 replica.cpp:508] Replica received write request for position 1 I0913 07:19:54.163597 5765 leveldb.cpp:343] Persisting action (157 bytes) to leveldb took 269392ns I0913 07:19:54.163614 5765 replica.cpp:676] Persisted action at 1 I0913 07:19:54.176707 5762 replica.cpp:655] Replica received learned notice for position 1 I0913 07:19:54.176998 5762 leveldb.cpp:343] Persisting action (159 bytes) to leveldb took 271316ns I0913 07:19:54.177016 5762 replica.cpp:676] Persisted action at 1 I0913 07:19:54.177026 5762 replica.cpp:661] Replica learned APPEND action at position 1 I0913 07:19:54.177290 5762 registrar.cpp:479] Successfully updated 'registry' I0913 07:19:54.177328 5762 registrar.cpp:372] Successfully recovered registrar I0913 07:19:54.177368 5762 log.cpp:699] Attempting to truncate the log to 1 I0913 07:19:54.177435 5762 master.cpp:1070] Recovered 0 slaves from the Registry (100B) ; allowing 10mins for slaves to re-register I0913 07:19:54.177480 5762 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2 I0913 07:19:54.177713 5762 replica.cpp:508] Replica received write request for position 2 I0913 07:19:54.177824 5762 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 93092ns I0913 07:19:54.177841 5762 replica.cpp:676] Persisted action at 2 I0913 07:19:54.178014 5762 replica.cpp:655] Replica received learned notice for position 2 I0913 07:19:54.178115 5762 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 85568ns I0913 07:19:54.178143 5762 leveldb.cpp:401] Deleting ~1 keys from leveldb took 12602ns I0913 07:19:54.178155 5762 replica.cpp:676] Persisted action at 2 I0913 07:19:54.284097 5762 replica.cpp:661] Replica learned TRUNCATE action at position 2 I0913 07:19:54.294366 5764 slave.cpp:169] Slave started on 115)@67.195.81.187:57627 I0913 07:19:54.294389 5764 credentials.hpp:84] Loading credential for authentication from '/tmp/GarbageCollectorIntegrationTest_DiskUsage_1giBe1/credential' I0913 07:19:54.294466 5764 slave.cpp:276] Slave using credential for: test-principal I0913 07:19:54.294569 5764 slave.cpp:289] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] I0913 07:19:54.294627 5764 slave.cpp:317] Slave hostname: pomona.apache.org I0913 07:19:54.294639 5764 slave.cpp:318] Slave checkpoint: false I0913 07:19:54.295058 5764 state.cpp:33] Recovering state from '/tmp/GarbageCollectorIntegrationTest_DiskUsage_1giBe1/meta' I0913 07:19:54.295155 5764 status_update_manager.cpp:193] Recovering status update manager I0913 07:19:54.295239 5764 slave.cpp:3219] Finished recovery I0913 07:19:54.295469 5764 slave.cpp:600] New master detected at [email protected]:57627 I0913 07:19:54.295492 5764 slave.cpp:674] Authenticating with master [email protected]:57627 I0913 07:19:54.295533 5764 slave.cpp:647] Detecting new master I0913 07:19:54.295568 5764 status_update_manager.cpp:167] New master detected at [email protected]:57627 I0913 07:19:54.295603 5764 authenticatee.hpp:128] Creating new client SASL connection I0913 07:19:54.295697 5764 master.cpp:3653] Authenticating slave(115)@67.195.81.187:57627 I0913 07:19:54.295781 5764 authenticator.hpp:156] Creating new server SASL connection I0913 07:19:54.295841 5764 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5 I0913 07:19:54.295860 5764 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5' I0913 07:19:54.295886 5764 authenticator.hpp:262] Received SASL authentication start I0913 07:19:54.295920 5764 authenticator.hpp:384] Authentication requires more steps I0913 07:19:54.295948 5764 authenticatee.hpp:265] Received SASL authentication step I0913 07:19:54.295987 5764 authenticator.hpp:290] Received SASL authentication step I0913 07:19:54.296005 5764 auxprop.cpp:81] 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 I0913 07:19:54.296015 5764 auxprop.cpp:153] Looking up auxiliary property '*userPassword' I0913 07:19:54.296030 5764 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0913 07:19:54.296042 5764 auxprop.cpp:81] 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 I0913 07:19:54.296051 5764 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0913 07:19:54.296058 5764 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0913 07:19:54.296073 5764 authenticator.hpp:376] Authentication success I0913 07:19:54.296103 5764 authenticatee.hpp:305] Authentication success I0913 07:19:54.296128 5764 master.cpp:3693] Successfully authenticated principal 'test-principal' at slave(115)@67.195.81.187:57627 I0913 07:19:54.296193 5764 slave.cpp:731] Successfully authenticated with master [email protected]:57627 I0913 07:19:54.296231 5764 slave.cpp:994] Will retry registration in 19.491161ms if necessary I0913 07:19:54.296299 5764 master.cpp:2843] Registering slave at slave(115)@67.195.81.187:57627 (pomona.apache.org) with id 20140913-071954-3142697795-57627-5741-0 I0913 07:19:54.296406 5764 registrar.cpp:422] Attempting to update the 'registry' I0913 07:19:54.297817 5764 log.cpp:680] Attempting to append 332 bytes to the log I0913 07:19:54.297863 5764 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3 I0913 07:19:54.298079 5764 replica.cpp:508] Replica received write request for position 3 I0913 07:19:54.298280 5764 leveldb.cpp:343] Persisting action (351 bytes) to leveldb took 180777ns I0913 07:19:54.298295 5764 replica.cpp:676] Persisted action at 3 I0913 07:19:54.298491 5764 replica.cpp:655] Replica received learned notice for position 3 I0913 07:19:54.298826 5764 leveldb.cpp:343] Persisting action (353 bytes) to leveldb took 318226ns I0913 07:19:54.298843 5764 replica.cpp:676] Persisted action at 3 I0913 07:19:54.298853 5764 replica.cpp:661] Replica learned APPEND action at position 3 I0913 07:19:54.299161 5764 registrar.cpp:479] Successfully updated 'registry' I0913 07:19:54.299239 5764 log.cpp:699] Attempting to truncate the log to 3 I0913 07:19:54.299294 5764 master.cpp:2883] Registered slave 20140913-071954-3142697795-57627-5741-0 at slave(115)@67.195.81.187:57627 (pomona.apache.org) I0913 07:19:54.299310 5764 master.cpp:4126] Adding slave 20140913-071954-3142697795-57627-5741-0 at slave(115)@67.195.81.187:57627 (pomona.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] I0913 07:19:54.299408 5764 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4 I0913 07:19:54.299609 5764 slave.cpp:765] Registered with master [email protected]:57627; given slave ID 20140913-071954-3142697795-57627-5741-0 I0913 07:19:54.299644 5764 slave.cpp:2346] Received ping from slave-observer(110)@67.195.81.187:57627 I0913 07:19:54.299737 5766 hierarchical_allocator_process.hpp:442] Added slave 20140913-071954-3142697795-57627-5741-0 (pomona.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] available) I0913 07:19:54.299783 5766 hierarchical_allocator_process.hpp:679] Performed allocation for slave 20140913-071954-3142697795-57627-5741-0 in 9179ns I0913 07:19:54.300092 5770 replica.cpp:508] Replica received write request for position 4 I0913 07:19:54.300190 5770 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 80047ns I0913 07:19:54.300207 5770 replica.cpp:676] Persisted action at 4 I0913 07:19:54.300384 5770 replica.cpp:655] Replica received learned notice for position 4 I0913 07:19:54.300495 5770 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 93807ns I0913 07:19:54.300531 5770 leveldb.cpp:401] Deleting ~2 keys from leveldb took 20239ns I0913 07:19:54.300544 5770 replica.cpp:676] Persisted action at 4 I0913 07:19:54.300554 5770 replica.cpp:661] Replica learned TRUNCATE action at position 4 I0913 07:19:54.304338 5741 sched.cpp:137] Version: 0.21.0 I0913 07:19:54.304476 5768 sched.cpp:233] New master detected at [email protected]:57627 I0913 07:19:54.304496 5768 sched.cpp:283] Authenticating with master [email protected]:57627 I0913 07:19:54.304569 5768 authenticatee.hpp:128] Creating new client SASL connection I0913 07:19:54.304647 5768 master.cpp:3653] Authenticating [email protected]:57627 I0913 07:19:54.304719 5768 authenticator.hpp:156] Creating new server SASL connection I0913 07:19:54.304766 5768 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5 I0913 07:19:54.304782 5768 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5' I0913 07:19:54.304807 5768 authenticator.hpp:262] Received SASL authentication start I0913 07:19:54.304836 5768 authenticator.hpp:384] Authentication requires more steps I0913 07:19:54.304863 5768 authenticatee.hpp:265] Received SASL authentication step I0913 07:19:54.304895 5768 authenticator.hpp:290] Received SASL authentication step I0913 07:19:54.304909 5768 auxprop.cpp:81] 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 I0913 07:19:54.304919 5768 auxprop.cpp:153] Looking up auxiliary property '*userPassword' I0913 07:19:54.304931 5768 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0913 07:19:54.443526 5768 auxprop.cpp:81] 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 I0913 07:19:54.443553 5768 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0913 07:19:54.443562 5768 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0913 07:19:54.443584 5768 authenticator.hpp:376] Authentication success I0913 07:19:54.443661 5768 authenticatee.hpp:305] Authentication success I0913 07:19:54.443694 5768 master.cpp:3693] Successfully authenticated principal 'test-principal' at [email protected]:57627 I0913 07:19:54.443804 5768 sched.cpp:357] Successfully authenticated with master [email protected]:57627 I0913 07:19:54.443819 5768 sched.cpp:476] Sending registration request to [email protected]:57627 I0913 07:19:54.443877 5768 master.cpp:1331] Received registration request from [email protected]:57627 I0913 07:19:54.443897 5768 master.cpp:1291] Authorizing framework principal 'test-principal' to receive offers for role '*' I0913 07:19:54.444013 5768 master.cpp:1390] Registering framework 20140913-071954-3142697795-57627-5741-0000 at [email protected]:57627 I0913 07:19:54.444118 5768 sched.cpp:407] Framework registered with 20140913-071954-3142697795-57627-5741-0000 I0913 07:19:54.444149 5768 sched.cpp:421] Scheduler::registered took 17894ns I0913 07:19:54.444187 5768 hierarchical_allocator_process.hpp:329] Added framework 20140913-071954-3142697795-57627-5741-0000 I0913 07:19:54.444243 5768 hierarchical_allocator_process.hpp:734] Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140913-071954-3142697795-57627-5741-0 to framework 20140913-071954-3142697795-57627-5741-0000 I0913 07:19:54.444365 5768 hierarchical_allocator_process.hpp:659] Performed allocation for 1 slaves in 161797ns I0913 07:19:54.444483 5768 master.hpp:861] Adding offer 20140913-071954-3142697795-57627-5741-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140913-071954-3142697795-57627-5741-0 (pomona.apache.org) I0913 07:19:54.444546 5768 master.cpp:3600] Sending 1 offers to framework 20140913-071954-3142697795-57627-5741-0000 I0913 07:19:54.444841 5768 sched.cpp:544] Scheduler::resourceOffers took 151672ns I0913 07:19:54.444995 5768 master.hpp:871] Removing offer 20140913-071954-3142697795-57627-5741-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140913-071954-3142697795-57627-5741-0 (pomona.apache.org) I0913 07:19:54.445056 5768 master.cpp:2201] Processing reply for offers: [ 20140913-071954-3142697795-57627-5741-0 ] on slave 20140913-071954-3142697795-57627-5741-0 at slave(115)@67.195.81.187:57627 (pomona.apache.org) for framework 20140913-071954-3142697795-57627-5741-0000 I0913 07:19:54.445082 5768 master.cpp:2284] Authorizing framework principal 'test-principal' to launch task 0 as user 'jenkins' I0913 07:19:54.445339 5768 master.hpp:833] Adding task 0 with resources cpus(*):2; mem(*):1024 on slave 20140913-071954-3142697795-57627-5741-0 (pomona.apache.org) I0913 07:19:54.445369 5768 master.cpp:2350] Launching task 0 of framework 20140913-071954-3142697795-57627-5741-0000 with resources cpus(*):2; mem(*):1024 on slave 20140913-071954-3142697795-57627-5741-0 at slave(115)@67.195.81.187:57627 (pomona.apache.org) I0913 07:19:54.445502 5768 slave.cpp:1025] Got assigned task 0 for framework 20140913-071954-3142697795-57627-5741-0000 I0913 07:19:54.445680 5768 slave.cpp:1135] Launching task 0 for framework 20140913-071954-3142697795-57627-5741-0000 I0913 07:19:54.448526 5768 exec.cpp:132] Version: 0.21.0 I0913 07:19:54.448623 5768 slave.cpp:1248] Queuing task '0' for executor default of framework '20140913-071954-3142697795-57627-5741-0000 I0913 07:19:54.448680 5768 slave.cpp:2559] Monitoring executor 'default' of framework '20140913-071954-3142697795-57627-5741-0000' in container 'a2addb81-3f56-4cb4-a6bb-15f71470200b' I0913 07:19:54.448765 5768 hierarchical_allocator_process.hpp:563] Recovered disk(*):1024; ports(*):[31000-32000] (total allocatable: disk(*):1024; ports(*):[31000-32000]) on slave 20140913-071954-3142697795-57627-5741-0 from framework 20140913-071954-3142697795-57627-5741-0000 I0913 07:19:54.448789 5768 hierarchical_allocator_process.hpp:599] Framework 20140913-071954-3142697795-57627-5741-0000 filtered slave 20140913-071954-3142697795-57627-5741-0 for 5secs I0913 07:19:54.448873 5768 exec.cpp:182] Executor started at: executor(46)@67.195.81.187:57627 with pid 5741 I0913 07:19:54.448938 5768 slave.cpp:554] Successfully attached file '/tmp/GarbageCollectorIntegrationTest_DiskUsage_1giBe1/slaves/20140913-071954-3142697795-57627-5741-0/frameworks/20140913-071954-3142697795-57627-5741-0000/executors/default/runs/a2addb81-3f56-4cb4-a6bb-15f71470200b' I0913 07:19:54.448966 5768 slave.cpp:1758] Got registration for executor 'default' of framework 20140913-071954-3142697795-57627-5741-0000 I0913 07:19:54.449045 5768 slave.cpp:1876] Flushing queued task 0 for executor 'default' of framework 20140913-071954-3142697795-57627-5741-0000 I0913 07:19:54.449118 5768 exec.cpp:206] Executor registered on slave 20140913-071954-3142697795-57627-5741-0 I0913 07:19:54.450222 5768 exec.cpp:218] Executor::registered took 11985ns I0913 07:19:54.450271 5768 exec.cpp:293] Executor asked to run task '0' I0913 07:19:54.450304 5768 exec.cpp:302] Executor::launchTask took 19918ns I0913 07:19:54.451616 5768 exec.cpp:525] Executor sending status update TASK_RUNNING (UUID: 5bdd3ad8-348b-4305-83ca-2e77d1f1175b) for task 0 of framework 20140913-071954-3142697795-57627-5741-0000 I0913 07:19:54.451692 5768 slave.cpp:2110] Handling status update TASK_RUNNING (UUID: 5bdd3ad8-348b-4305-83ca-2e77d1f1175b) for task 0 of framework 20140913-071954-3142697795-57627-5741-0000 from executor(46)@67.195.81.187:57627 I0913 07:19:54.451771 5768 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: 5bdd3ad8-348b-4305-83ca-2e77d1f1175b) for task 0 of framework 20140913-071954-3142697795-57627-5741-0000 I0913 07:19:54.451786 5768 status_update_manager.cpp:499] Creating StatusUpdate stream for task 0 of framework 20140913-071954-3142697795-57627-5741-0000 I0913 07:19:54.451850 5768 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: 5bdd3ad8-348b-4305-83ca-2e77d1f1175b) for task 0 of framework 20140913-071954-3142697795-57627-5741-0000 to [email protected]:57627 I0913 07:19:54.451954 5768 master.cpp:3212] Forwarding status update TASK_RUNNING (UUID: 5bdd3ad8-348b-4305-83ca-2e77d1f1175b) for task 0 of framework 20140913-071954-3142697795-57627-5741-0000 I0913 07:19:54.451992 5768 master.cpp:3178] Status update TASK_RUNNING (UUID: 5bdd3ad8-348b-4305-83ca-2e77d1f1175b) for task 0 of framework 20140913-071954-3142697795-57627-5741-0000 from slave 20140913-071954-3142697795-57627-5741-0 at slave(115)@67.195.81.187:57627 (pomona.apache.org) I0913 07:19:54.452024 5768 slave.cpp:2267] Status update manager successfully handled status update TASK_RUNNING (UUID: 5bdd3ad8-348b-4305-83ca-2e77d1f1175b) for task 0 of framework 20140913-071954-3142697795-57627-5741-0000 I0913 07:19:54.452038 5768 slave.cpp:2273] Sending acknowledgement for status update TASK_RUNNING (UUID: 5bdd3ad8-348b-4305-83ca-2e77d1f1175b) for task 0 of framework 20140913-071954-3142697795-57627-5741-0000 to executor(46)@67.195.81.187:57627 I0913 07:19:54.452107 5768 sched.cpp:635] Scheduler::statusUpdate took 12841ns I0913 07:19:54.452147 5768 exec.cpp:339] Executor received status update acknowledgement 5bdd3ad8-348b-4305-83ca-2e77d1f1175b for task 0 of framework 20140913-071954-3142697795-57627-5741-0000 I0913 07:19:54.452191 5768 master.cpp:2693] Forwarding status update acknowledgement 5bdd3ad8-348b-4305-83ca-2e77d1f1175b for task 0 of framework 20140913-071954-3142697795-57627-5741-0000 to slave 20140913-071954-3142697795-57627-5741-0 at slave(115)@67.195.81.187:57627 (pomona.apache.org) I0913 07:19:54.452261 5768 status_update_manager.cpp:398] Received status update acknowledgement (UUID: 5bdd3ad8-348b-4305-83ca-2e77d1f1175b) for task 0 of framework 20140913-071954-3142697795-57627-5741-0000 I0913 07:19:54.452311 5768 slave.cpp:1698] Status update manager successfully handled status update acknowledgement (UUID: 5bdd3ad8-348b-4305-83ca-2e77d1f1175b) for task 0 of framework 20140913-071954-3142697795-57627-5741-0000 I0913 07:19:54.452644 5762 slave.cpp:2617] Executor 'default' of framework 20140913-071954-3142697795-57627-5741-0000 exited with status 0 I0913 07:19:54.453768 5762 slave.cpp:2110] Handling status update TASK_LOST (UUID: 3b98bbdf-bc1b-407e-afec-c4e4ec10c159) for task 0 of framework 20140913-071954-3142697795-57627-5741-0000 from @0.0.0.0:0 I0913 07:19:54.453794 5762 slave.cpp:3937] Terminating task 0 I0913 07:19:54.453968 5762 master.cpp:3261] Executor default of framework 20140913-071954-3142697795-57627-5741-0000 on slave 20140913-071954-3142697795-57627-5741-0 at slave(115)@67.195.81.187:57627 (pomona.apache.org) exited with status 0 I0913 07:19:54.454020 5762 status_update_manager.cpp:320] Received status update TASK_LOST (UUID: 3b98bbdf-bc1b-407e-afec-c4e4ec10c159) for task 0 of framework 20140913-071954-3142697795-57627-5741-0000 I0913 07:19:54.454042 5762 status_update_manager.cpp:373] Forwarding status update TASK_LOST (UUID: 3b98bbdf-bc1b-407e-afec-c4e4ec10c159) for task 0 of framework 20140913-071954-3142697795-57627-5741-0000 to [email protected]:57627 I0913 07:19:54.454145 5762 master.cpp:3212] Forwarding status update TASK_LOST (UUID: 3b98bbdf-bc1b-407e-afec-c4e4ec10c159) for task 0 of framework 20140913-071954-3142697795-57627-5741-0000 I0913 07:19:54.454182 5762 master.cpp:3178] Status update TASK_LOST (UUID: 3b98bbdf-bc1b-407e-afec-c4e4ec10c159) for task 0 of framework 20140913-071954-3142697795-57627-5741-0000 from slave 20140913-071954-3142697795-57627-5741-0 at slave(115)@67.195.81.187:57627 (pomona.apache.org) I0913 07:19:54.454217 5762 master.hpp:851] Removing task 0 with resources cpus(*):2; mem(*):1024 on slave 20140913-071954-3142697795-57627-5741-0 (pomona.apache.org) I0913 07:19:54.454282 5762 slave.cpp:2267] Status update manager successfully handled status update TASK_LOST (UUID: 3b98bbdf-bc1b-407e-afec-c4e4ec10c159) for task 0 of framework 20140913-071954-3142697795-57627-5741-0000 I0913 07:19:54.454340 5762 sched.cpp:635] Scheduler::statusUpdate took 8274ns I0913 07:19:54.454402 5762 hierarchical_allocator_process.hpp:563] Recovered cpus(*):2; mem(*):1024 (total allocatable: disk(*):1024; ports(*):[31000-32000]; cpus(*):2; mem(*):1024) on slave 20140913-071954-3142697795-57627-5741-0 from framework 20140913-071954-3142697795-57627-5741-0000 I0913 07:19:54.454449 5762 master.cpp:2693] Forwarding status update acknowledgement 3b98bbdf-bc1b-407e-afec-c4e4ec10c159 for task 0 of framework 20140913-071954-3142697795-57627-5741-0000 to slave 20140913-071954-3142697795-57627-5741-0 at slave(115)@67.195.81.187:57627 (pomona.apache.org) I0913 07:19:54.454516 5762 status_update_manager.cpp:398] Received status update acknowledgement (UUID: 3b98bbdf-bc1b-407e-afec-c4e4ec10c159) for task 0 of framework 20140913-071954-3142697795-57627-5741-0000 I0913 07:19:54.454540 5762 status_update_manager.cpp:530] Cleaning up status update stream for task 0 of framework 20140913-071954-3142697795-57627-5741-0000 I0913 07:19:54.454592 5762 slave.cpp:1698] Status update manager successfully handled status update acknowledgement (UUID: 3b98bbdf-bc1b-407e-afec-c4e4ec10c159) for task 0 of framework 20140913-071954-3142697795-57627-5741-0000 I0913 07:19:54.454608 5762 slave.cpp:3976] Completing task 0 I0913 07:19:54.454619 5762 slave.cpp:2753] Cleaning up executor 'default' of framework 20140913-071954-3142697795-57627-5741-0000 I0913 07:19:56.779952 5762 slave.cpp:2828] Cleaning up framework 20140913-071954-3142697795-57627-5741-0000 I0913 07:19:56.780050 5762 gc.cpp:56] Scheduling '/tmp/GarbageCollectorIntegrationTest_DiskUsage_1giBe1/slaves/20140913-071954-3142697795-57627-5741-0/frameworks/20140913-071954-3142697795-57627-5741-0000/executors/default/runs/a2addb81-3f56-4cb4-a6bb-15f71470200b' for gc 1.00000255872weeks in the future I0913 07:19:56.780107 5762 gc.cpp:56] Scheduling '/tmp/GarbageCollectorIntegrationTest_DiskUsage_1giBe1/slaves/20140913-071954-3142697795-57627-5741-0/frameworks/20140913-071954-3142697795-57627-5741-0000/executors/default' for gc 1.00000255872weeks in the future I0913 07:19:56.780138 5762 gc.cpp:56] Scheduling '/tmp/GarbageCollectorIntegrationTest_DiskUsage_1giBe1/slaves/20140913-071954-3142697795-57627-5741-0/frameworks/20140913-071954-3142697795-57627-5741-0000' for gc 1.00000255872weeks in the future I0913 07:19:56.780169 5762 status_update_manager.cpp:282] Closing status update streams for framework 20140913-071954-3142697795-57627-5741-0000 I0913 07:19:56.798529 5762 hierarchical_allocator_process.hpp:734] Offering disk(*):1024; ports(*):[31000-32000]; cpus(*):2; mem(*):1024 on slave 20140913-071954-3142697795-57627-5741-0 to framework 20140913-071954-3142697795-57627-5741-0000 I0913 07:19:56.798661 5762 hierarchical_allocator_process.hpp:659] Performed allocation for 1 slaves in 193142ns I0913 07:19:56.798741 5762 master.hpp:861] Adding offer 20140913-071954-3142697795-57627-5741-1 with resources disk(*):1024; ports(*):[31000-32000]; cpus(*):2; mem(*):1024 on slave 20140913-071954-3142697795-57627-5741-0 (pomona.apache.org) I0913 07:19:56.798812 5762 master.cpp:3600] Sending 1 offers to framework 20140913-071954-3142697795-57627-5741-0000 I0913 07:19:56.798944 5762 sched.cpp:544] Scheduler::resourceOffers took 11292ns I0913 07:19:56.799255 5760 slave.cpp:3074] Current usage 90.00%. Max allowed age: 0ns ../../src/tests/gc_tests.cpp:675: Failure Value of: os::exists(executorDir) Actual: true Expected: false I0913 07:19:56.828771 5767 master.cpp:741] Framework 20140913-071954-3142697795-57627-5741-0000 disconnected I0913 07:19:56.828795 5767 master.cpp:1687] Deactivating framework 20140913-071954-3142697795-57627-5741-0000 I0913 07:19:56.828909 5767 master.hpp:871] Removing offer 20140913-071954-3142697795-57627-5741-1 with resources disk(*):1024; ports(*):[31000-32000]; cpus(*):2; mem(*):1024 on slave 20140913-071954-3142697795-57627-5741-0 (pomona.apache.org) I0913 07:19:56.828982 5767 master.cpp:763] Giving framework 20140913-071954-3142697795-57627-5741-0000 0ns to failover I0913 07:19:56.829025 5767 hierarchical_allocator_process.hpp:405] Deactivated framework 20140913-071954-3142697795-57627-5741-0000 I0913 07:19:56.829110 5767 hierarchical_allocator_process.hpp:563] Recovered disk(*):1024; ports(*):[31000-32000]; cpus(*):2; mem(*):1024 (total allocatable: disk(*):1024; ports(*):[31000-32000]; cpus(*):2; mem(*):1024) on slave 20140913-071954-3142697795-57627-5741-0 from framework 20140913-071954-3142697795-57627-5741-0000 I0913 07:19:56.829191 5767 master.cpp:3471] Framework failover timeout, removing framework 20140913-071954-3142697795-57627-5741-0000 I0913 07:19:56.829202 5767 master.cpp:3976] Removing framework 20140913-071954-3142697795-57627-5741-0000 I0913 07:19:56.829273 5767 slave.cpp:1431] Asked to shut down framework 20140913-071954-3142697795-57627-5741-0000 by [email protected]:57627 W0913 07:19:56.829289 5767 slave.cpp:1446] Cannot shut down unknown framework 20140913-071954-3142697795-57627-5741-0000 I0913 07:19:56.829355 5767 hierarchical_allocator_process.hpp:360] Removed framework 20140913-071954-3142697795-57627-5741-0000 I0913 07:19:56.849370 5755 master.cpp:650] Master terminating I0913 07:19:56.862035 5758 slave.cpp:2378] [email protected]:57627 exited W0913 07:19:56.862061 5758 slave.cpp:2381] Master disconnected! Waiting for a new master to be elected F0913 07:19:56.862061 5741 logging.cpp:57] RAW: Pure virtual method called @ 0x2ba13b61148d google::LogMessage::Fail() @ 0x2ba13b618b86 google::RawLog__() @ 0x4ff0b6 mesos::internal::tests::Cluster::Slaves::shutdown() @ 0x77bde4 mesos::internal::tests::MesosTest::ShutdownSlaves() @ 0x944c13 testing::internal::HandleExceptionsInMethodIfSupported<>() @ 0x93bdb0 testing::Test::Run() @ 0x93be8e testing::TestInfo::Run() @ 0x93bf95 testing::TestCase::Run() @ 0x93c238 testing::internal::UnitTestImpl::RunAllTests() @ 0x93c4d7 testing::UnitTest::Run() @ 0x48d3f3 main @ 0x2ba13d325ec5 (unknown) @ 0x49a708 (unknown) make[3]: *** [check-local] Aborted 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
