See <https://builds.apache.org/job/Mesos-Ubuntu-distcheck/59/>
------------------------------------------ [...truncated 18017 lines...] I0427 05:54:50.255856 18423 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 15.543616ms I0427 05:54:50.255882 18423 replica.cpp:664] Persisted action at 4 I0427 05:54:50.256211 18410 slave.cpp:414] Slave terminating [ OK ] FaultToleranceTest.ReconcileLostTasks (304 ms) [ RUN ] FaultToleranceTest.ReconcileIncompleteTasks I0427 05:54:50.308887 18380 leveldb.cpp:174] Opened db in 49.966139ms I0427 05:54:50.325147 18380 leveldb.cpp:181] Compacted db in 16.232125ms I0427 05:54:50.325178 18380 leveldb.cpp:196] Created db iterator in 3304ns I0427 05:54:50.325189 18380 leveldb.cpp:202] Seeked to beginning of db in 453ns I0427 05:54:50.325198 18380 leveldb.cpp:271] Iterated through 0 keys in the db in 198ns I0427 05:54:50.325211 18380 replica.cpp:729] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0427 05:54:50.325427 18409 recover.cpp:425] Starting replica recovery I0427 05:54:50.325664 18421 recover.cpp:451] Replica is in EMPTY status I0427 05:54:50.327237 18413 replica.cpp:626] Replica in EMPTY status received a broadcasted recover request I0427 05:54:50.327430 18403 master.cpp:266] Master 20140427-055450-453759884-58871-18380 (hemera.apache.org) started on 140.211.11.27:58871 I0427 05:54:50.327453 18403 master.cpp:303] Master only allowing authenticated frameworks to register I0427 05:54:50.327466 18403 master.cpp:308] Master only allowing authenticated slaves to register I0427 05:54:50.327474 18403 credentials.hpp:35] Loading credentials for authentication W0427 05:54:50.328032 18403 credentials.hpp:48] Failed to stat credentials file 'file:///tmp/FaultToleranceTest_ReconcileIncompleteTasks_08suky/credentials': No such file or directory I0427 05:54:50.328040 18417 recover.cpp:188] Received a recover response from a replica in EMPTY status I0427 05:54:50.328825 18415 master.cpp:104] No whitelist given. Advertising offers for all slaves I0427 05:54:50.329061 18404 hierarchical_allocator_process.hpp:302] Initializing hierarchical allocator process with master : [email protected]:58871 I0427 05:54:50.329176 18417 recover.cpp:542] Updating replica status to STARTING I0427 05:54:50.330179 18401 master.cpp:922] The newly elected leader is [email protected]:58871 with id 20140427-055450-453759884-58871-18380 I0427 05:54:50.330200 18401 master.cpp:932] Elected as the leading master! I0427 05:54:50.330209 18401 master.cpp:753] Recovering from registrar I0427 05:54:50.330513 18413 registrar.cpp:275] Recovering registrar I0427 05:54:50.345291 18400 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 15.706993ms I0427 05:54:50.345322 18400 replica.cpp:320] Persisted replica status to STARTING I0427 05:54:50.345420 18400 recover.cpp:451] Replica is in STARTING status I0427 05:54:50.347443 18403 replica.cpp:626] Replica in STARTING status received a broadcasted recover request I0427 05:54:50.347615 18407 recover.cpp:188] Received a recover response from a replica in STARTING status I0427 05:54:50.348222 18416 recover.cpp:542] Updating replica status to VOTING I0427 05:54:50.365392 18407 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 16.765647ms I0427 05:54:50.365423 18407 replica.cpp:320] Persisted replica status to VOTING I0427 05:54:50.365491 18407 recover.cpp:556] Successfully joined the Paxos group I0427 05:54:50.365578 18407 recover.cpp:440] Recover process terminated I0427 05:54:50.366667 18410 log.cpp:656] Attempting to start the writer I0427 05:54:50.369606 18400 replica.cpp:474] Replica received implicit promise request with proposal 1 I0427 05:54:50.385444 18400 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 15.810942ms I0427 05:54:50.385474 18400 replica.cpp:342] Persisted promised to 1 I0427 05:54:50.385953 18415 coordinator.cpp:229] Coordinator attemping to fill missing position I0427 05:54:50.389475 18402 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2 I0427 05:54:50.405491 18402 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 15.98652ms I0427 05:54:50.405521 18402 replica.cpp:664] Persisted action at 0 I0427 05:54:50.407254 18423 replica.cpp:508] Replica received write request for position 0 I0427 05:54:50.407302 18423 leveldb.cpp:436] Reading position from leveldb took 11910ns I0427 05:54:50.421561 18423 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 14.240509ms I0427 05:54:50.421591 18423 replica.cpp:664] Persisted action at 0 I0427 05:54:50.422715 18407 replica.cpp:643] Replica received learned notice for position 0 I0427 05:54:50.437647 18407 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 14.908141ms I0427 05:54:50.437685 18407 replica.cpp:664] Persisted action at 0 I0427 05:54:50.437703 18407 replica.cpp:649] Replica learned NOP action at position 0 I0427 05:54:50.438292 18423 log.cpp:672] Writer started with ending position 0 I0427 05:54:50.440260 18408 leveldb.cpp:436] Reading position from leveldb took 11833ns I0427 05:54:50.442945 18414 registrar.cpp:308] Successfully recovered registrar I0427 05:54:50.442977 18414 registrar.cpp:379] Attempting to update the 'registry' I0427 05:54:50.445209 18410 log.cpp:680] Attempting to append 138 bytes to the log I0427 05:54:50.445374 18422 coordinator.cpp:339] Coordinator attempting to write APPEND action at position 1 I0427 05:54:50.447042 18413 replica.cpp:508] Replica received write request for position 1 I0427 05:54:50.461766 18413 leveldb.cpp:341] Persisting action (157 bytes) to leveldb took 14.693361ms I0427 05:54:50.461802 18413 replica.cpp:664] Persisted action at 1 I0427 05:54:50.462342 18410 replica.cpp:643] Replica received learned notice for position 1 I0427 05:54:50.473862 18410 leveldb.cpp:341] Persisting action (159 bytes) to leveldb took 11.484481ms I0427 05:54:50.473896 18410 replica.cpp:664] Persisted action at 1 I0427 05:54:50.473908 18410 replica.cpp:649] Replica learned APPEND action at position 1 I0427 05:54:50.474349 18420 registrar.cpp:427] Successfully updated 'registry' I0427 05:54:50.474601 18420 master.cpp:780] Recovered 0 slaves from the Registry (100B) ; allowing 10mins for slaves to re-register I0427 05:54:50.474876 18414 log.cpp:699] Attempting to truncate the log to 1 I0427 05:54:50.474947 18419 coordinator.cpp:339] Coordinator attempting to write TRUNCATE action at position 2 I0427 05:54:50.475389 18404 replica.cpp:508] Replica received write request for position 2 I0427 05:54:50.478407 18405 slave.cpp:140] Slave started on 48)@140.211.11.27:58871 I0427 05:54:50.478431 18405 credentials.hpp:35] Loading credentials for authentication W0427 05:54:50.478803 18405 credentials.hpp:48] Failed to stat credentials file 'file:///tmp/FaultToleranceTest_ReconcileIncompleteTasks_Mfj51o/credential': No such file or directory I0427 05:54:50.478842 18405 slave.cpp:231] Slave using credential for: test-principal I0427 05:54:50.478994 18405 slave.cpp:244] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] I0427 05:54:50.479122 18405 slave.cpp:272] Slave hostname: hemera.apache.org I0427 05:54:50.479141 18405 slave.cpp:273] Slave checkpoint: false I0427 05:54:50.479974 18407 state.cpp:33] Recovering state from '/tmp/FaultToleranceTest_ReconcileIncompleteTasks_Mfj51o/meta' I0427 05:54:50.480329 18407 status_update_manager.cpp:193] Recovering status update manager I0427 05:54:50.480548 18406 slave.cpp:2943] Finished recovery I0427 05:54:50.481844 18380 sched.cpp:121] Version: 0.19.0 I0427 05:54:50.482112 18418 sched.cpp:217] New master detected at [email protected]:58871 I0427 05:54:50.482251 18418 sched.cpp:268] Authenticating with master [email protected]:58871 I0427 05:54:50.482332 18416 slave.cpp:525] New master detected at [email protected]:58871 I0427 05:54:50.482547 18416 slave.cpp:585] Authenticating with master [email protected]:58871 I0427 05:54:50.482600 18410 status_update_manager.cpp:167] New master detected at [email protected]:58871 I0427 05:54:50.482961 18400 authenticatee.hpp:128] Creating new client SASL connection I0427 05:54:50.483093 18400 master.cpp:2795] Authenticating scheduler(55)@140.211.11.27:58871 I0427 05:54:50.483177 18400 authenticator.hpp:148] Creating new server SASL connection I0427 05:54:50.483320 18409 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5 I0427 05:54:50.483343 18409 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5' I0427 05:54:50.483409 18401 authenticator.hpp:254] Received SASL authentication start I0427 05:54:50.483507 18401 authenticator.hpp:342] Authentication requires more steps I0427 05:54:50.483559 18401 authenticatee.hpp:265] Received SASL authentication step I0427 05:54:50.483624 18401 authenticator.hpp:282] Received SASL authentication step I0427 05:54:50.483656 18401 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 I0427 05:54:50.483670 18401 auxprop.cpp:153] Looking up auxiliary property '*userPassword' I0427 05:54:50.483688 18401 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0427 05:54:50.483688 18416 slave.cpp:558] Detecting new master I0427 05:54:50.483705 18401 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 I0427 05:54:50.483717 18401 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0427 05:54:50.483726 18401 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0427 05:54:50.483747 18401 authenticator.hpp:334] Authentication success I0427 05:54:50.483809 18408 authenticatee.hpp:128] Creating new client SASL connection I0427 05:54:50.484097 18403 authenticatee.hpp:305] Authentication success I0427 05:54:50.484129 18418 master.cpp:2835] Successfully authenticated scheduler(55)@140.211.11.27:58871 I0427 05:54:50.484169 18403 sched.cpp:342] Successfully authenticated with master [email protected]:58871 I0427 05:54:50.484185 18403 sched.cpp:461] Sending registration request to [email protected]:58871 I0427 05:54:50.484235 18418 master.cpp:2795] Authenticating slave(48)@140.211.11.27:58871 I0427 05:54:50.484397 18412 authenticator.hpp:148] Creating new server SASL connection I0427 05:54:50.484438 18418 master.cpp:981] Received registration request from scheduler(55)@140.211.11.27:58871 I0427 05:54:50.484480 18418 master.cpp:999] Registering framework 20140427-055450-453759884-58871-18380-0000 at scheduler(55)@140.211.11.27:58871 I0427 05:54:50.484675 18421 sched.cpp:392] Framework registered with 20140427-055450-453759884-58871-18380-0000 I0427 05:54:50.484763 18421 sched.cpp:406] Scheduler::registered took 69143ns I0427 05:54:50.484814 18418 hierarchical_allocator_process.hpp:332] Added framework 20140427-055450-453759884-58871-18380-0000 I0427 05:54:50.484835 18418 hierarchical_allocator_process.hpp:726] No resources available to allocate! I0427 05:54:50.484848 18418 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 14041ns I0427 05:54:50.485307 18408 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5 I0427 05:54:50.485332 18408 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5' I0427 05:54:50.485373 18408 authenticator.hpp:254] Received SASL authentication start I0427 05:54:50.485421 18408 authenticator.hpp:342] Authentication requires more steps I0427 05:54:50.485455 18408 authenticatee.hpp:265] Received SASL authentication step I0427 05:54:50.486012 18404 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 10.598346ms I0427 05:54:50.486039 18404 replica.cpp:664] Persisted action at 2 I0427 05:54:50.486311 18414 authenticator.hpp:282] Received SASL authentication step I0427 05:54:50.486352 18414 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 I0427 05:54:50.486361 18414 auxprop.cpp:153] Looking up auxiliary property '*userPassword' I0427 05:54:50.486371 18414 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0427 05:54:50.486381 18414 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 I0427 05:54:50.486387 18414 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0427 05:54:50.486393 18414 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0427 05:54:50.486407 18414 authenticator.hpp:334] Authentication success I0427 05:54:50.486701 18408 authenticatee.hpp:305] Authentication success I0427 05:54:50.486806 18405 master.cpp:2835] Successfully authenticated slave(48)@140.211.11.27:58871 I0427 05:54:50.487254 18415 replica.cpp:643] Replica received learned notice for position 2 I0427 05:54:50.487490 18408 slave.cpp:642] Successfully authenticated with master [email protected]:58871 I0427 05:54:50.487627 18408 slave.cpp:871] Will retry registration in 6.984128326secs if necessary I0427 05:54:50.487912 18422 registrar.cpp:379] Attempting to update the 'registry' I0427 05:54:50.498257 18415 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 10.9821ms I0427 05:54:50.498311 18415 leveldb.cpp:399] Deleting ~1 keys from leveldb took 25414ns I0427 05:54:50.498325 18415 replica.cpp:664] Persisted action at 2 I0427 05:54:50.498334 18415 replica.cpp:649] Replica learned TRUNCATE action at position 2 I0427 05:54:50.498839 18423 log.cpp:680] Attempting to append 332 bytes to the log I0427 05:54:50.499119 18420 coordinator.cpp:339] Coordinator attempting to write APPEND action at position 3 I0427 05:54:50.499893 18420 replica.cpp:508] Replica received write request for position 3 I0427 05:54:50.510323 18420 leveldb.cpp:341] Persisting action (351 bytes) to leveldb took 10.400041ms I0427 05:54:50.510354 18420 replica.cpp:664] Persisted action at 3 I0427 05:54:50.511579 18416 replica.cpp:643] Replica received learned notice for position 3 I0427 05:54:50.522435 18416 leveldb.cpp:341] Persisting action (353 bytes) to leveldb took 10.83367ms I0427 05:54:50.522477 18416 replica.cpp:664] Persisted action at 3 I0427 05:54:50.522488 18416 replica.cpp:649] Replica learned APPEND action at position 3 I0427 05:54:50.523043 18403 registrar.cpp:427] Successfully updated 'registry' I0427 05:54:50.523776 18423 master.cpp:2169] Admitted slave on hemera.apache.org at slave(48)@140.211.11.27:58871 I0427 05:54:50.523797 18400 log.cpp:699] Attempting to truncate the log to 3 I0427 05:54:50.523799 18423 master.cpp:3283] Adding slave 20140427-055450-453759884-58871-18380-0 at hemera.apache.org with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] I0427 05:54:50.523897 18411 coordinator.cpp:339] Coordinator attempting to write TRUNCATE action at position 4 I0427 05:54:50.523936 18400 slave.cpp:675] Registered with master [email protected]:58871; given slave ID 20140427-055450-453759884-58871-18380-0 I0427 05:54:50.524178 18415 hierarchical_allocator_process.hpp:445] Added slave 20140427-055450-453759884-58871-18380-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) I0427 05:54:50.524257 18415 hierarchical_allocator_process.hpp:752] Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140427-055450-453759884-58871-18380-0 to framework 20140427-055450-453759884-58871-18380-0000 I0427 05:54:50.524703 18415 hierarchical_allocator_process.hpp:708] Performed allocation for slave 20140427-055450-453759884-58871-18380-0 in 470389ns I0427 05:54:50.524833 18416 master.hpp:586] Adding offer 20140427-055450-453759884-58871-18380-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140427-055450-453759884-58871-18380-0 (hemera.apache.org) I0427 05:54:50.524914 18416 master.cpp:2744] Sending 1 offers to framework 20140427-055450-453759884-58871-18380-0000 I0427 05:54:50.525650 18413 replica.cpp:508] Replica received write request for position 4 I0427 05:54:50.525720 18421 sched.cpp:529] Scheduler::resourceOffers took 27501ns I0427 05:54:50.526586 18405 master.hpp:596] Removing offer 20140427-055450-453759884-58871-18380-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140427-055450-453759884-58871-18380-0 (hemera.apache.org) I0427 05:54:50.526695 18405 master.cpp:1806] Processing reply for offers: [ 20140427-055450-453759884-58871-18380-0 ] on slave 20140427-055450-453759884-58871-18380-0 (hemera.apache.org) for framework 20140427-055450-453759884-58871-18380-0000 I0427 05:54:50.526885 18405 master.hpp:558] Adding task 1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140427-055450-453759884-58871-18380-0 (hemera.apache.org) I0427 05:54:50.526984 18405 master.cpp:2919] Launching task 1 of framework 20140427-055450-453759884-58871-18380-0000 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140427-055450-453759884-58871-18380-0 (hemera.apache.org) I0427 05:54:50.527168 18418 slave.cpp:905] Got assigned task 1 for framework 20140427-055450-453759884-58871-18380-0000 I0427 05:54:50.527384 18418 slave.cpp:1015] Launching task 1 for framework 20140427-055450-453759884-58871-18380-0000 I0427 05:54:50.531828 18418 exec.cpp:131] Version: 0.19.0 I0427 05:54:50.531893 18403 exec.cpp:181] Executor started at: executor(29)@140.211.11.27:58871 with pid 18380 I0427 05:54:50.531985 18418 slave.cpp:1125] Queuing task '1' for executor default of framework '20140427-055450-453759884-58871-18380-0000 I0427 05:54:50.532040 18418 slave.cpp:486] Successfully attached file '/tmp/FaultToleranceTest_ReconcileIncompleteTasks_Mfj51o/slaves/20140427-055450-453759884-58871-18380-0/frameworks/20140427-055450-453759884-58871-18380-0000/executors/default/runs/c9718618-f55a-4ddf-87a4-74aad6a0917a' I0427 05:54:50.532065 18418 slave.cpp:2282] Monitoring executor 'default' of framework '20140427-055450-453759884-58871-18380-0000' in container 'c9718618-f55a-4ddf-87a4-74aad6a0917a' I0427 05:54:50.532155 18418 slave.cpp:1598] Got registration for executor 'default' of framework 20140427-055450-453759884-58871-18380-0000 I0427 05:54:50.532281 18418 slave.cpp:1717] Flushing queued task 1 for executor 'default' of framework 20140427-055450-453759884-58871-18380-0000 I0427 05:54:50.532330 18414 exec.cpp:205] Executor registered on slave 20140427-055450-453759884-58871-18380-0 I0427 05:54:50.534528 18414 exec.cpp:217] Executor::registered took 14909ns I0427 05:54:50.534600 18414 exec.cpp:292] Executor asked to run task '1' I0427 05:54:50.534636 18414 exec.cpp:301] Executor::launchTask took 22608ns I0427 05:54:50.536613 18414 exec.cpp:524] Executor sending status update TASK_FINISHED (UUID: 8263f92e-21d6-4f74-937c-6383a8d93a00) for task 1 of framework 20140427-055450-453759884-58871-18380-0000 I0427 05:54:50.536706 18414 slave.cpp:1953] Handling status update TASK_FINISHED (UUID: 8263f92e-21d6-4f74-937c-6383a8d93a00) for task 1 of framework 20140427-055450-453759884-58871-18380-0000 from executor(29)@140.211.11.27:58871 I0427 05:54:50.536736 18414 slave.cpp:3444] Terminating task 1 I0427 05:54:50.536859 18414 status_update_manager.cpp:320] Received status update TASK_FINISHED (UUID: 8263f92e-21d6-4f74-937c-6383a8d93a00) for task 1 of framework 20140427-055450-453759884-58871-18380-0000 I0427 05:54:50.536942 18414 status_update_manager.cpp:499] Creating StatusUpdate stream for task 1 of framework 20140427-055450-453759884-58871-18380-0000 I0427 05:54:50.536993 18414 status_update_manager.cpp:373] Forwarding status update TASK_FINISHED (UUID: 8263f92e-21d6-4f74-937c-6383a8d93a00) for task 1 of framework 20140427-055450-453759884-58871-18380-0000 to [email protected]:58871 I0427 05:54:50.537364 18417 slave.cpp:2070] Status update manager successfully handled status update TASK_FINISHED (UUID: 8263f92e-21d6-4f74-937c-6383a8d93a00) for task 1 of framework 20140427-055450-453759884-58871-18380-0000 I0427 05:54:50.537387 18417 slave.cpp:2076] Sending acknowledgement for status update TASK_FINISHED (UUID: 8263f92e-21d6-4f74-937c-6383a8d93a00) for task 1 of framework 20140427-055450-453759884-58871-18380-0000 to executor(29)@140.211.11.27:58871 I0427 05:54:50.538363 18415 exec.cpp:338] Executor received status update acknowledgement 8263f92e-21d6-4f74-937c-6383a8d93a00 for task 1 of framework 20140427-055450-453759884-58871-18380-0000 I0427 05:54:50.538930 18413 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 13.256759ms I0427 05:54:50.538962 18413 replica.cpp:664] Persisted action at 4 I0427 05:54:50.539667 18402 replica.cpp:643] Replica received learned notice for position 4 I0427 05:54:50.550969 18402 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 11.277437ms I0427 05:54:50.551033 18402 leveldb.cpp:399] Deleting ~2 keys from leveldb took 34201ns I0427 05:54:50.551049 18402 replica.cpp:664] Persisted action at 4 I0427 05:54:50.551064 18402 replica.cpp:649] Replica learned TRUNCATE action at position 4 I0427 05:54:50.558732 18404 slave.cpp:525] New master detected at [email protected]:58871 I0427 05:54:50.558904 18404 slave.cpp:585] Authenticating with master [email protected]:58871 I0427 05:54:50.559273 18404 slave.cpp:558] Detecting new master I0427 05:54:50.559305 18402 authenticatee.hpp:128] Creating new client SASL connection I0427 05:54:50.559442 18417 status_update_manager.cpp:167] New master detected at [email protected]:58871 W0427 05:54:50.559537 18417 status_update_manager.cpp:181] Resending status update TASK_FINISHED (UUID: 8263f92e-21d6-4f74-937c-6383a8d93a00) for task 1 of framework 20140427-055450-453759884-58871-18380-0000 I0427 05:54:50.559556 18417 status_update_manager.cpp:373] Forwarding status update TASK_FINISHED (UUID: 8263f92e-21d6-4f74-937c-6383a8d93a00) for task 1 of framework 20140427-055450-453759884-58871-18380-0000 to [email protected]:58871 I0427 05:54:50.559905 18403 master.cpp:1263] Disconnecting slave 20140427-055450-453759884-58871-18380-0 I0427 05:54:50.559968 18403 master.cpp:1283] Removing non-checkpointing framework 20140427-055450-453759884-58871-18380-0000 from disconnected slave 20140427-055450-453759884-58871-18380-0(hemera.apache.org) I0427 05:54:50.559978 18403 master.cpp:3235] Removing framework 20140427-055450-453759884-58871-18380-0000 from slave 20140427-055450-453759884-58871-18380-0 (hemera.apache.org) I0427 05:54:50.560056 18409 hierarchical_allocator_process.hpp:484] Slave 20140427-055450-453759884-58871-18380-0 disconnected I0427 05:54:50.562168 18403 master.cpp:2444] Status update TASK_LOST (UUID: 06142cf1-d0ec-49df-8903-3a587fd87ffb) for task 1 of framework 20140427-055450-453759884-58871-18380-0000 from @0.0.0.0:0 I0427 05:54:50.562273 18423 sched.cpp:620] Scheduler::statusUpdate took 15301ns I0427 05:54:50.562283 18403 master.hpp:576] Removing task 1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140427-055450-453759884-58871-18380-0 (hemera.apache.org) I0427 05:54:50.562458 18403 master.cpp:2795] Authenticating slave(48)@140.211.11.27:58871 I0427 05:54:50.562562 18418 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 20140427-055450-453759884-58871-18380-0 from framework 20140427-055450-453759884-58871-18380-0000 I0427 05:54:50.562610 18400 authenticator.hpp:148] Creating new server SASL connection W0427 05:54:50.562724 18403 master.cpp:2437] Status update TASK_FINISHED (UUID: 8263f92e-21d6-4f74-937c-6383a8d93a00) for task 1 of framework 20140427-055450-453759884-58871-18380-0000 from slave(48)@140.211.11.27:58871 (hemera.apache.org): error, couldn't lookup task I0427 05:54:50.562983 18410 sched.cpp:620] Scheduler::statusUpdate took 10490ns I0427 05:54:50.563199 18405 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5 I0427 05:54:50.563230 18411 status_update_manager.cpp:398] Received status update acknowledgement (UUID: 8263f92e-21d6-4f74-937c-6383a8d93a00) for task 1 of framework 20140427-055450-453759884-58871-18380-0000 I0427 05:54:50.563237 18405 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5' I0427 05:54:50.563343 18411 status_update_manager.cpp:530] Cleaning up status update stream for task 1 of framework 20140427-055450-453759884-58871-18380-0000 I0427 05:54:50.563424 18411 slave.cpp:1538] Status update manager successfully handled status update acknowledgement (UUID: 8263f92e-21d6-4f74-937c-6383a8d93a00) for task 1 of framework 20140427-055450-453759884-58871-18380-0000 I0427 05:54:50.563452 18411 slave.cpp:3468] Completing task 1 I0427 05:54:50.563644 18418 authenticator.hpp:254] Received SASL authentication start I0427 05:54:50.563701 18418 authenticator.hpp:342] Authentication requires more steps I0427 05:54:50.563745 18418 authenticatee.hpp:265] Received SASL authentication step I0427 05:54:50.563791 18418 authenticator.hpp:282] Received SASL authentication step I0427 05:54:50.563807 18418 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 I0427 05:54:50.563817 18418 auxprop.cpp:153] Looking up auxiliary property '*userPassword' I0427 05:54:50.563827 18418 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0427 05:54:50.563837 18418 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 I0427 05:54:50.563843 18418 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0427 05:54:50.563849 18418 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0427 05:54:50.563863 18418 authenticator.hpp:334] Authentication success I0427 05:54:50.563912 18412 authenticatee.hpp:305] Authentication success I0427 05:54:50.563918 18418 master.cpp:2835] Successfully authenticated slave(48)@140.211.11.27:58871 I0427 05:54:50.564594 18413 slave.cpp:642] Successfully authenticated with master [email protected]:58871 I0427 05:54:50.564795 18413 slave.cpp:871] Will retry registration in 7.554142627secs if necessary W0427 05:54:50.564926 18418 master.cpp:2244] Slave at slave(48)@140.211.11.27:58871 (hemera.apache.org) is being allowed to re-register with an already in use id (20140427-055450-453759884-58871-18380-0) I0427 05:54:50.565045 18418 slave.cpp:725] Re-registered with master [email protected]:58871 I0427 05:54:50.565083 18404 hierarchical_allocator_process.hpp:498] Slave 20140427-055450-453759884-58871-18380-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. /bin/bash: line 9: 17170 Terminated ( CDPATH="${ZSH_VERSION+.}:" && cd $subdir && make $local_target ) make[1]: *** [check-recursive] Terminated make: *** [distcheck] Terminated
