See <https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/2102/changes>
Changes: [benjamin.hindman] Fix URL decoding of '+' as space. [vinod] Used security group names to look up clusters instead of security group [bmahler] Fixed a flaky use of FUTURE_DISPATCH. ------------------------------------------ [...truncated 18144 lines...] [ RUN ] FaultToleranceTest.ReconcileIncompleteTasks I0430 17:24:22.620306 10584 leveldb.cpp:174] Opened db in 39.29572ms I0430 17:24:22.628639 10584 leveldb.cpp:181] Compacted db in 8.303557ms I0430 17:24:22.628674 10584 leveldb.cpp:196] Created db iterator in 4129ns I0430 17:24:22.628684 10584 leveldb.cpp:202] Seeked to beginning of db in 802ns I0430 17:24:22.628690 10584 leveldb.cpp:271] Iterated through 0 keys in the db in 303ns I0430 17:24:22.628705 10584 replica.cpp:729] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0430 17:24:22.628921 10611 recover.cpp:425] Starting replica recovery I0430 17:24:22.629179 10611 recover.cpp:451] Replica is in EMPTY status I0430 17:24:22.630064 10614 master.cpp:266] Master 20140430-172422-453759884-51291-10584 (hemera.apache.org) started on 140.211.11.27:51291 I0430 17:24:22.630092 10614 master.cpp:303] Master only allowing authenticated frameworks to register I0430 17:24:22.630096 10614 master.cpp:308] Master only allowing authenticated slaves to register I0430 17:24:22.630100 10614 credentials.hpp:35] Loading credentials for authentication W0430 17:24:22.630214 10614 credentials.hpp:48] Failed to stat credentials file 'file:///tmp/FaultToleranceTest_ReconcileIncompleteTasks_Tv4wU5/credentials': No such file or directory I0430 17:24:22.630487 10622 hierarchical_allocator_process.hpp:302] Initializing hierarchical allocator process with master : [email protected]:51291 I0430 17:24:22.630565 10619 master.cpp:104] No whitelist given. Advertising offers for all slaves I0430 17:24:22.630620 10616 replica.cpp:626] Replica in EMPTY status received a broadcasted recover request I0430 17:24:22.630928 10611 recover.cpp:188] Received a recover response from a replica in EMPTY status I0430 17:24:22.631552 10611 recover.cpp:542] Updating replica status to STARTING I0430 17:24:22.631728 10626 master.cpp:922] The newly elected leader is [email protected]:51291 with id 20140430-172422-453759884-51291-10584 I0430 17:24:22.631752 10626 master.cpp:932] Elected as the leading master! I0430 17:24:22.631759 10626 master.cpp:753] Recovering from registrar I0430 17:24:22.631834 10606 registrar.cpp:275] Recovering registrar I0430 17:24:22.649065 10616 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 17.317228ms I0430 17:24:22.649087 10616 replica.cpp:320] Persisted replica status to STARTING I0430 17:24:22.649144 10616 recover.cpp:451] Replica is in STARTING status I0430 17:24:22.649750 10623 replica.cpp:626] Replica in STARTING status received a broadcasted recover request I0430 17:24:22.650703 10610 recover.cpp:188] Received a recover response from a replica in STARTING status I0430 17:24:22.651103 10626 recover.cpp:542] Updating replica status to VOTING I0430 17:24:22.669179 10617 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 17.282802ms I0430 17:24:22.669199 10617 replica.cpp:320] Persisted replica status to VOTING I0430 17:24:22.669342 10617 recover.cpp:556] Successfully joined the Paxos group I0430 17:24:22.669419 10617 recover.cpp:440] Recover process terminated I0430 17:24:22.669519 10623 log.cpp:656] Attempting to start the writer I0430 17:24:22.671129 10606 replica.cpp:474] Replica received implicit promise request with proposal 1 I0430 17:24:22.689234 10606 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 18.087773ms I0430 17:24:22.689254 10606 replica.cpp:342] Persisted promised to 1 I0430 17:24:22.689596 10604 coordinator.cpp:229] Coordinator attemping to fill missing position I0430 17:24:22.690723 10621 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2 I0430 17:24:22.705322 10621 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 14.582011ms I0430 17:24:22.705345 10621 replica.cpp:664] Persisted action at 0 I0430 17:24:22.706953 10606 replica.cpp:508] Replica received write request for position 0 I0430 17:24:22.706979 10606 leveldb.cpp:436] Reading position from leveldb took 12566ns I0430 17:24:22.721411 10606 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 14.417943ms I0430 17:24:22.721431 10606 replica.cpp:664] Persisted action at 0 I0430 17:24:22.722000 10610 replica.cpp:643] Replica received learned notice for position 0 I0430 17:24:22.737509 10610 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 15.477282ms I0430 17:24:22.737529 10610 replica.cpp:664] Persisted action at 0 I0430 17:24:22.737537 10610 replica.cpp:649] Replica learned NOP action at position 0 I0430 17:24:22.737884 10624 log.cpp:672] Writer started with ending position 0 I0430 17:24:22.739698 10605 leveldb.cpp:436] Reading position from leveldb took 9204ns I0430 17:24:22.741179 10606 registrar.cpp:308] Successfully recovered registrar I0430 17:24:22.741302 10606 registrar.cpp:379] Attempting to update the 'registry' I0430 17:24:22.742338 10617 log.cpp:680] Attempting to append 138 bytes to the log I0430 17:24:22.742517 10618 coordinator.cpp:339] Coordinator attempting to write APPEND action at position 1 I0430 17:24:22.743352 10622 replica.cpp:508] Replica received write request for position 1 I0430 17:24:22.761575 10622 leveldb.cpp:341] Persisting action (157 bytes) to leveldb took 18.19671ms I0430 17:24:22.761617 10622 replica.cpp:664] Persisted action at 1 I0430 17:24:22.762220 10610 replica.cpp:643] Replica received learned notice for position 1 I0430 17:24:22.777649 10610 leveldb.cpp:341] Persisting action (159 bytes) to leveldb took 15.414078ms I0430 17:24:22.777670 10610 replica.cpp:664] Persisted action at 1 I0430 17:24:22.777679 10610 replica.cpp:649] Replica learned APPEND action at position 1 I0430 17:24:22.777922 10606 registrar.cpp:427] Successfully updated 'registry' I0430 17:24:22.778146 10610 log.cpp:699] Attempting to truncate the log to 1 I0430 17:24:22.778403 10614 coordinator.cpp:339] Coordinator attempting to write TRUNCATE action at position 2 I0430 17:24:22.778527 10607 master.cpp:780] Recovered 0 slaves from the Registry (100B) ; allowing 10mins for slaves to re-register I0430 17:24:22.779458 10622 replica.cpp:508] Replica received write request for position 2 I0430 17:24:22.781586 10611 slave.cpp:140] Slave started on 66)@140.211.11.27:51291 I0430 17:24:22.781599 10611 credentials.hpp:35] Loading credentials for authentication W0430 17:24:22.781718 10611 credentials.hpp:48] Failed to stat credentials file 'file:///tmp/FaultToleranceTest_ReconcileIncompleteTasks_ryNl1x/credential': No such file or directory I0430 17:24:22.781738 10611 slave.cpp:231] Slave using credential for: test-principal I0430 17:24:22.781810 10611 slave.cpp:244] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] I0430 17:24:22.781915 10611 slave.cpp:272] Slave hostname: hemera.apache.org I0430 17:24:22.781926 10611 slave.cpp:273] Slave checkpoint: false I0430 17:24:22.782217 10612 state.cpp:33] Recovering state from '/tmp/FaultToleranceTest_ReconcileIncompleteTasks_ryNl1x/meta' I0430 17:24:22.782532 10604 status_update_manager.cpp:193] Recovering status update manager I0430 17:24:22.782704 10614 slave.cpp:2943] Finished recovery I0430 17:24:22.783084 10614 slave.cpp:525] New master detected at [email protected]:51291 I0430 17:24:22.783206 10614 slave.cpp:585] Authenticating with master [email protected]:51291 I0430 17:24:22.783229 10618 status_update_manager.cpp:167] New master detected at [email protected]:51291 I0430 17:24:22.783434 10614 slave.cpp:558] Detecting new master I0430 17:24:22.783470 10609 authenticatee.hpp:128] Creating new client SASL connection I0430 17:24:22.783732 10616 master.cpp:2795] Authenticating slave(66)@140.211.11.27:51291 I0430 17:24:22.783805 10616 authenticator.hpp:148] Creating new server SASL connection I0430 17:24:22.783921 10616 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5 I0430 17:24:22.783948 10616 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5' I0430 17:24:22.784101 10614 authenticator.hpp:254] Received SASL authentication start I0430 17:24:22.784135 10614 authenticator.hpp:342] Authentication requires more steps I0430 17:24:22.784184 10614 authenticatee.hpp:265] Received SASL authentication step I0430 17:24:22.784220 10614 authenticator.hpp:282] Received SASL authentication step I0430 17:24:22.784277 10614 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: 'hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I0430 17:24:22.784283 10614 auxprop.cpp:153] Looking up auxiliary property '*userPassword' I0430 17:24:22.784289 10614 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0430 17:24:22.784294 10614 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: 'hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I0430 17:24:22.784298 10614 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0430 17:24:22.784301 10614 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0430 17:24:22.784310 10614 authenticator.hpp:334] Authentication success I0430 17:24:22.784376 10584 sched.cpp:121] Version: 0.19.0 I0430 17:24:22.784445 10615 master.cpp:2835] Successfully authenticated slave(66)@140.211.11.27:51291 I0430 17:24:22.784451 10626 authenticatee.hpp:305] Authentication success I0430 17:24:22.784836 10620 sched.cpp:217] New master detected at [email protected]:51291 I0430 17:24:22.784858 10620 sched.cpp:268] Authenticating with master [email protected]:51291 I0430 17:24:22.785073 10612 authenticatee.hpp:128] Creating new client SASL connection I0430 17:24:22.785195 10608 master.cpp:2795] Authenticating scheduler(67)@140.211.11.27:51291 I0430 17:24:22.785213 10610 slave.cpp:642] Successfully authenticated with master [email protected]:51291 I0430 17:24:22.785249 10610 slave.cpp:871] Will retry registration in 6.473163993secs if necessary I0430 17:24:22.785293 10613 authenticator.hpp:148] Creating new server SASL connection I0430 17:24:22.785421 10626 registrar.cpp:379] Attempting to update the 'registry' I0430 17:24:22.785449 10603 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5 I0430 17:24:22.785502 10603 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5' I0430 17:24:22.785820 10609 authenticator.hpp:254] Received SASL authentication start I0430 17:24:22.785876 10609 authenticator.hpp:342] Authentication requires more steps I0430 17:24:22.785938 10604 authenticatee.hpp:265] Received SASL authentication step I0430 17:24:22.786061 10625 authenticator.hpp:282] Received SASL authentication step I0430 17:24:22.786079 10625 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: 'hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I0430 17:24:22.786087 10625 auxprop.cpp:153] Looking up auxiliary property '*userPassword' I0430 17:24:22.786093 10625 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0430 17:24:22.786101 10625 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: 'hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I0430 17:24:22.786108 10625 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0430 17:24:22.786113 10625 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0430 17:24:22.786123 10625 authenticator.hpp:334] Authentication success I0430 17:24:22.786162 10604 master.cpp:2835] Successfully authenticated scheduler(67)@140.211.11.27:51291 I0430 17:24:22.786183 10618 authenticatee.hpp:305] Authentication success I0430 17:24:22.786433 10620 sched.cpp:342] Successfully authenticated with master [email protected]:51291 I0430 17:24:22.786470 10620 sched.cpp:461] Sending registration request to [email protected]:51291 I0430 17:24:22.786526 10614 master.cpp:981] Received registration request from scheduler(67)@140.211.11.27:51291 I0430 17:24:22.786614 10614 master.cpp:999] Registering framework 20140430-172422-453759884-51291-10584-0000 at scheduler(67)@140.211.11.27:51291 I0430 17:24:22.786741 10617 sched.cpp:392] Framework registered with 20140430-172422-453759884-51291-10584-0000 I0430 17:24:22.786759 10617 sched.cpp:406] Scheduler::registered took 8173ns I0430 17:24:22.786775 10621 hierarchical_allocator_process.hpp:332] Added framework 20140430-172422-453759884-51291-10584-0000 I0430 17:24:22.786785 10621 hierarchical_allocator_process.hpp:726] No resources available to allocate! I0430 17:24:22.786790 10621 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 5362ns I0430 17:24:22.797955 10622 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 18.471279ms I0430 17:24:22.797979 10622 replica.cpp:664] Persisted action at 2 I0430 17:24:22.798358 10618 replica.cpp:643] Replica received learned notice for position 2 I0430 17:24:22.814254 10618 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 15.872893ms I0430 17:24:22.814324 10618 leveldb.cpp:399] Deleting ~1 keys from leveldb took 34648ns I0430 17:24:22.814339 10618 replica.cpp:664] Persisted action at 2 I0430 17:24:22.814349 10618 replica.cpp:649] Replica learned TRUNCATE action at position 2 I0430 17:24:22.814676 10603 log.cpp:680] Attempting to append 332 bytes to the log I0430 17:24:22.814935 10604 coordinator.cpp:339] Coordinator attempting to write APPEND action at position 3 I0430 17:24:22.816246 10612 replica.cpp:508] Replica received write request for position 3 I0430 17:24:22.834553 10612 leveldb.cpp:341] Persisting action (351 bytes) to leveldb took 18.280805ms I0430 17:24:22.834600 10612 replica.cpp:664] Persisted action at 3 I0430 17:24:22.835142 10616 replica.cpp:643] Replica received learned notice for position 3 I0430 17:24:22.854887 10616 leveldb.cpp:341] Persisting action (353 bytes) to leveldb took 19.651357ms I0430 17:24:22.854925 10616 replica.cpp:664] Persisted action at 3 I0430 17:24:22.854936 10616 replica.cpp:649] Replica learned APPEND action at position 3 I0430 17:24:22.855361 10616 registrar.cpp:427] Successfully updated 'registry' I0430 17:24:22.855451 10616 log.cpp:699] Attempting to truncate the log to 3 I0430 17:24:22.855512 10616 master.cpp:2169] Admitted slave on hemera.apache.org at slave(66)@140.211.11.27:51291 I0430 17:24:22.855525 10616 master.cpp:3283] Adding slave 20140430-172422-453759884-51291-10584-0 at hemera.apache.org with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] I0430 17:24:22.855640 10616 coordinator.cpp:339] Coordinator attempting to write TRUNCATE action at position 4 I0430 17:24:22.855712 10616 slave.cpp:675] Registered with master [email protected]:51291; given slave ID 20140430-172422-453759884-51291-10584-0 I0430 17:24:22.855787 10616 hierarchical_allocator_process.hpp:445] Added slave 20140430-172422-453759884-51291-10584-0 (hemera.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] available) I0430 17:24:22.855854 10616 hierarchical_allocator_process.hpp:752] Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140430-172422-453759884-51291-10584-0 to framework 20140430-172422-453759884-51291-10584-0000 I0430 17:24:22.855968 10616 hierarchical_allocator_process.hpp:708] Performed allocation for slave 20140430-172422-453759884-51291-10584-0 in 146098ns I0430 17:24:22.856062 10616 master.hpp:586] Adding offer 20140430-172422-453759884-51291-10584-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140430-172422-453759884-51291-10584-0 (hemera.apache.org) I0430 17:24:22.856107 10616 master.cpp:2744] Sending 1 offers to framework 20140430-172422-453759884-51291-10584-0000 I0430 17:24:22.856256 10616 sched.cpp:529] Scheduler::resourceOffers took 20775ns I0430 17:24:22.856453 10616 replica.cpp:508] Replica received write request for position 4 I0430 17:24:22.856987 10614 master.hpp:596] Removing offer 20140430-172422-453759884-51291-10584-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140430-172422-453759884-51291-10584-0 (hemera.apache.org) I0430 17:24:22.857043 10614 master.cpp:1806] Processing reply for offers: [ 20140430-172422-453759884-51291-10584-0 ] on slave 20140430-172422-453759884-51291-10584-0 (hemera.apache.org) for framework 20140430-172422-453759884-51291-10584-0000 I0430 17:24:22.857149 10614 master.hpp:558] Adding task 1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140430-172422-453759884-51291-10584-0 (hemera.apache.org) I0430 17:24:22.857199 10614 master.cpp:2919] Launching task 1 of framework 20140430-172422-453759884-51291-10584-0000 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140430-172422-453759884-51291-10584-0 (hemera.apache.org) I0430 17:24:22.857329 10610 slave.cpp:905] Got assigned task 1 for framework 20140430-172422-453759884-51291-10584-0000 I0430 17:24:22.857520 10610 slave.cpp:1015] Launching task 1 for framework 20140430-172422-453759884-51291-10584-0000 I0430 17:24:22.859944 10610 exec.cpp:131] Version: 0.19.0 I0430 17:24:22.860049 10610 slave.cpp:1125] Queuing task '1' for executor default of framework '20140430-172422-453759884-51291-10584-0000 I0430 17:24:22.860060 10604 exec.cpp:181] Executor started at: executor(17)@140.211.11.27:51291 with pid 10584 I0430 17:24:22.860195 10610 slave.cpp:486] Successfully attached file '/tmp/FaultToleranceTest_ReconcileIncompleteTasks_ryNl1x/slaves/20140430-172422-453759884-51291-10584-0/frameworks/20140430-172422-453759884-51291-10584-0000/executors/default/runs/d49a603c-9b0a-484f-888c-9c8e4f58e295' I0430 17:24:22.860214 10610 slave.cpp:2282] Monitoring executor 'default' of framework '20140430-172422-453759884-51291-10584-0000' in container 'd49a603c-9b0a-484f-888c-9c8e4f58e295' I0430 17:24:22.860383 10610 slave.cpp:1598] Got registration for executor 'default' of framework 20140430-172422-453759884-51291-10584-0000 I0430 17:24:22.860579 10610 slave.cpp:1717] Flushing queued task 1 for executor 'default' of framework 20140430-172422-453759884-51291-10584-0000 I0430 17:24:22.860640 10613 exec.cpp:205] Executor registered on slave 20140430-172422-453759884-51291-10584-0 I0430 17:24:22.861618 10613 exec.cpp:217] Executor::registered took 10377ns I0430 17:24:22.861661 10613 exec.cpp:292] Executor asked to run task '1' I0430 17:24:22.861685 10613 exec.cpp:301] Executor::launchTask took 15799ns I0430 17:24:22.862452 10613 exec.cpp:524] Executor sending status update TASK_FINISHED (UUID: 2e896c9d-36d3-42b6-8939-a28a1c19544c) for task 1 of framework 20140430-172422-453759884-51291-10584-0000 I0430 17:24:22.862514 10613 slave.cpp:1953] Handling status update TASK_FINISHED (UUID: 2e896c9d-36d3-42b6-8939-a28a1c19544c) for task 1 of framework 20140430-172422-453759884-51291-10584-0000 from executor(17)@140.211.11.27:51291 I0430 17:24:22.862540 10613 slave.cpp:3444] Terminating task 1 I0430 17:24:22.862612 10613 status_update_manager.cpp:320] Received status update TASK_FINISHED (UUID: 2e896c9d-36d3-42b6-8939-a28a1c19544c) for task 1 of framework 20140430-172422-453759884-51291-10584-0000 I0430 17:24:22.862649 10613 status_update_manager.cpp:499] Creating StatusUpdate stream for task 1 of framework 20140430-172422-453759884-51291-10584-0000 I0430 17:24:22.862694 10613 status_update_manager.cpp:373] Forwarding status update TASK_FINISHED (UUID: 2e896c9d-36d3-42b6-8939-a28a1c19544c) for task 1 of framework 20140430-172422-453759884-51291-10584-0000 to [email protected]:51291 I0430 17:24:22.862812 10613 slave.cpp:2070] Status update manager successfully handled status update TASK_FINISHED (UUID: 2e896c9d-36d3-42b6-8939-a28a1c19544c) for task 1 of framework 20140430-172422-453759884-51291-10584-0000 I0430 17:24:22.862869 10613 slave.cpp:2076] Sending acknowledgement for status update TASK_FINISHED (UUID: 2e896c9d-36d3-42b6-8939-a28a1c19544c) for task 1 of framework 20140430-172422-453759884-51291-10584-0000 to executor(17)@140.211.11.27:51291 I0430 17:24:22.862897 10613 exec.cpp:338] Executor received status update acknowledgement 2e896c9d-36d3-42b6-8939-a28a1c19544c for task 1 of framework 20140430-172422-453759884-51291-10584-0000 I0430 17:24:22.875960 10616 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 19.488919ms I0430 17:24:22.875984 10616 replica.cpp:664] Persisted action at 4 I0430 17:24:22.876183 10622 replica.cpp:643] Replica received learned notice for position 4 I0430 17:24:22.892046 10622 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 15.84996ms I0430 17:24:22.892103 10622 leveldb.cpp:399] Deleting ~2 keys from leveldb took 38291ns I0430 17:24:22.892112 10622 replica.cpp:664] Persisted action at 4 I0430 17:24:22.892118 10622 replica.cpp:649] Replica learned TRUNCATE action at position 4 I0430 17:24:22.898475 10622 slave.cpp:525] New master detected at [email protected]:51291 I0430 17:24:22.898501 10622 slave.cpp:585] Authenticating with master [email protected]:51291 I0430 17:24:22.898535 10622 slave.cpp:558] Detecting new master I0430 17:24:22.898581 10622 authenticatee.hpp:128] Creating new client SASL connection I0430 17:24:22.898582 10615 status_update_manager.cpp:167] New master detected at [email protected]:51291 W0430 17:24:22.898599 10615 status_update_manager.cpp:181] Resending status update TASK_FINISHED (UUID: 2e896c9d-36d3-42b6-8939-a28a1c19544c) for task 1 of framework 20140430-172422-453759884-51291-10584-0000 I0430 17:24:22.898713 10615 status_update_manager.cpp:373] Forwarding status update TASK_FINISHED (UUID: 2e896c9d-36d3-42b6-8939-a28a1c19544c) for task 1 of framework 20140430-172422-453759884-51291-10584-0000 to [email protected]:51291 I0430 17:24:22.898890 10619 master.cpp:1263] Disconnecting slave 20140430-172422-453759884-51291-10584-0 I0430 17:24:22.899091 10619 master.cpp:1283] Removing non-checkpointing framework 20140430-172422-453759884-51291-10584-0000 from disconnected slave 20140430-172422-453759884-51291-10584-0(hemera.apache.org) I0430 17:24:22.899103 10619 master.cpp:3235] Removing framework 20140430-172422-453759884-51291-10584-0000 from slave 20140430-172422-453759884-51291-10584-0 (hemera.apache.org) I0430 17:24:22.899119 10608 hierarchical_allocator_process.hpp:484] Slave 20140430-172422-453759884-51291-10584-0 disconnected I0430 17:24:22.899956 10619 master.cpp:2444] Status update TASK_LOST (UUID: 6ae302ff-1921-450a-84fb-109462c19aa1) for task 1 of framework 20140430-172422-453759884-51291-10584-0000 from @0.0.0.0:0 I0430 17:24:22.900017 10619 master.hpp:576] Removing task 1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140430-172422-453759884-51291-10584-0 (hemera.apache.org) I0430 17:24:22.900041 10615 sched.cpp:620] Scheduler::statusUpdate took 12809ns I0430 17:24:22.900110 10619 master.cpp:2795] Authenticating slave(66)@140.211.11.27:51291 I0430 17:24:22.900147 10622 hierarchical_allocator_process.hpp:637] Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total allocatable: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) on slave 20140430-172422-453759884-51291-10584-0 from framework 20140430-172422-453759884-51291-10584-0000 I0430 17:24:22.900274 10604 authenticator.hpp:148] Creating new server SASL connection W0430 17:24:22.900291 10619 master.cpp:2437] Status update TASK_FINISHED (UUID: 2e896c9d-36d3-42b6-8939-a28a1c19544c) for task 1 of framework 20140430-172422-453759884-51291-10584-0000 from slave(66)@140.211.11.27:51291 (hemera.apache.org): error, couldn't lookup task I0430 17:24:22.900336 10619 sched.cpp:620] Scheduler::statusUpdate took 7460ns I0430 17:24:22.900989 10608 status_update_manager.cpp:398] Received status update acknowledgement (UUID: 2e896c9d-36d3-42b6-8939-a28a1c19544c) for task 1 of framework 20140430-172422-453759884-51291-10584-0000 I0430 17:24:22.901012 10608 status_update_manager.cpp:530] Cleaning up status update stream for task 1 of framework 20140430-172422-453759884-51291-10584-0000 I0430 17:24:22.901170 10612 slave.cpp:1538] Status update manager successfully handled status update acknowledgement (UUID: 2e896c9d-36d3-42b6-8939-a28a1c19544c) for task 1 of framework 20140430-172422-453759884-51291-10584-0000 I0430 17:24:22.901218 10612 slave.cpp:3468] Completing task 1 I0430 17:24:22.901253 10621 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5 I0430 17:24:22.901276 10621 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5' I0430 17:24:22.901373 10603 authenticator.hpp:254] Received SASL authentication start I0430 17:24:22.901408 10603 authenticator.hpp:342] Authentication requires more steps I0430 17:24:22.901437 10603 authenticatee.hpp:265] Received SASL authentication step I0430 17:24:22.901465 10603 authenticator.hpp:282] Received SASL authentication step I0430 17:24:22.901587 10603 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: 'hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I0430 17:24:22.901593 10603 auxprop.cpp:153] Looking up auxiliary property '*userPassword' I0430 17:24:22.901600 10603 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0430 17:24:22.901605 10603 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: 'hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I0430 17:24:22.901609 10603 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0430 17:24:22.901612 10603 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0430 17:24:22.901619 10603 authenticator.hpp:334] Authentication success I0430 17:24:22.901643 10603 authenticatee.hpp:305] Authentication success I0430 17:24:22.901679 10607 master.cpp:2835] Successfully authenticated slave(66)@140.211.11.27:51291 I0430 17:24:22.901938 10603 slave.cpp:642] Successfully authenticated with master [email protected]:51291 I0430 17:24:22.901985 10603 slave.cpp:871] Will retry registration in 9.066182251secs if necessary W0430 17:24:22.902063 10607 master.cpp:2244] Slave at slave(66)@140.211.11.27:51291 (hemera.apache.org) is being allowed to re-register with an already in use id (20140430-172422-453759884-51291-10584-0) I0430 17:24:22.902356 10621 slave.cpp:725] Re-registered with master [email protected]:51291 I0430 17:24:22.902410 10626 hierarchical_allocator_process.hpp:498] Slave 20140430-172422-453759884-51291-10584-0 reconnected ../../src/tests/fault_tolerance_tests.cpp:2084: Failure Value of: status.get().state() Actual: TASK_LOST Expected: TASK_FINISHED Build timed out (after 120 minutes). Marking the build as failed. make[3]: *** [check-local] Terminated make[3]: Leaving directory `/x1/jenkins/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/build/src' make[2]: *** [check-am] Error 2 make[2]: Leaving directory `/x1/jenkins/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/build/src' make[1]: *** [check] Error 2 make[1]: Leaving directory `/x1/jenkins/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/build/src' make: *** [check-recursive] Error 1
