See <https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/2230/changes>
Changes: [vinodkone] Added MesosCon'14 playlist to presentations. ------------------------------------------ [...truncated 15872 lines...] I1030 05:54:04.505708 29517 replica.cpp:676] Persisted action at 2 I1030 05:54:04.505733 29517 replica.cpp:661] Replica learned TRUNCATE action at position 2 I1030 05:54:04.518836 29520 slave.cpp:169] Slave started on 27)@67.195.81.187:54775 I1030 05:54:04.518879 29520 credentials.hpp:84] Loading credential for authentication from '/tmp/ReconciliationTest_TaskStateMismatch_jXTxgL/credential' I1030 05:54:04.519043 29520 slave.cpp:276] Slave using credential for: test-principal I1030 05:54:04.519332 29520 slave.cpp:289] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] I1030 05:54:04.519435 29520 slave.cpp:318] Slave hostname: pomona.apache.org I1030 05:54:04.519454 29520 slave.cpp:319] Slave checkpoint: false W1030 05:54:04.519462 29520 slave.cpp:321] Disabling checkpointing is deprecated and the --checkpoint flag will be removed in a future release. Please avoid using this flag I1030 05:54:04.520382 29526 state.cpp:33] Recovering state from '/tmp/ReconciliationTest_TaskStateMismatch_jXTxgL/meta' I1030 05:54:04.521198 29519 status_update_manager.cpp:197] Recovering status update manager I1030 05:54:04.521605 29521 slave.cpp:3456] Finished recovery I1030 05:54:04.522595 29515 status_update_manager.cpp:171] Pausing sending status updates I1030 05:54:04.522593 29524 slave.cpp:602] New master detected at [email protected]:54775 I1030 05:54:04.522677 29524 slave.cpp:665] Authenticating with master [email protected]:54775 I1030 05:54:04.522855 29524 slave.cpp:638] Detecting new master I1030 05:54:04.522924 29522 authenticatee.hpp:133] Creating new client SASL connection I1030 05:54:04.523164 29512 master.cpp:3853] Authenticating slave(27)@67.195.81.187:54775 I1030 05:54:04.523605 29523 authenticator.hpp:161] Creating new server SASL connection I1030 05:54:04.523784 29523 authenticatee.hpp:224] Received SASL authentication mechanisms: CRAM-MD5 I1030 05:54:04.523813 29523 authenticatee.hpp:250] Attempting to authenticate with mechanism 'CRAM-MD5' I1030 05:54:04.523910 29519 authenticator.hpp:267] Received SASL authentication start I1030 05:54:04.524049 29519 authenticator.hpp:389] Authentication requires more steps I1030 05:54:04.524139 29519 authenticatee.hpp:270] Received SASL authentication step I1030 05:54:04.524343 29524 authenticator.hpp:295] Received SASL authentication step I1030 05:54:04.524382 29524 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 I1030 05:54:04.524395 29524 auxprop.cpp:153] Looking up auxiliary property '*userPassword' I1030 05:54:04.524438 29524 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I1030 05:54:04.524466 29524 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 I1030 05:54:04.524479 29524 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I1030 05:54:04.524488 29524 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I1030 05:54:04.524507 29524 authenticator.hpp:381] Authentication success I1030 05:54:04.524592 29523 authenticatee.hpp:310] Authentication success I1030 05:54:04.524618 29524 master.cpp:3893] Successfully authenticated principal 'test-principal' at slave(27)@67.195.81.187:54775 I1030 05:54:04.524847 29519 slave.cpp:722] Successfully authenticated with master [email protected]:54775 I1030 05:54:04.525086 29519 slave.cpp:1050] Will retry registration in 1.045728ms if necessary I1030 05:54:04.525368 29524 master.cpp:3032] Registering slave at slave(27)@67.195.81.187:54775 (pomona.apache.org) with id 20141030-055359-3142697795-54775-29497-S0 I1030 05:54:04.525885 29523 registrar.cpp:445] Applied 1 operations in 94940ns; attempting to update the 'registry' I1030 05:54:04.526000 29497 sched.cpp:137] Version: 0.21.0 I1030 05:54:04.526583 29521 slave.cpp:1050] Will retry registration in 17.399441ms if necessary I1030 05:54:04.526733 29526 master.cpp:3020] Ignoring register slave message from slave(27)@67.195.81.187:54775 (pomona.apache.org) as admission is already in progress I1030 05:54:04.526758 29514 sched.cpp:233] New master detected at [email protected]:54775 I1030 05:54:04.526803 29514 sched.cpp:283] Authenticating with master [email protected]:54775 I1030 05:54:04.527016 29518 authenticatee.hpp:133] Creating new client SASL connection I1030 05:54:04.527230 29524 master.cpp:3853] Authenticating [email protected]:54775 I1030 05:54:04.527487 29512 authenticator.hpp:161] Creating new server SASL connection I1030 05:54:04.527606 29516 authenticatee.hpp:224] Received SASL authentication mechanisms: CRAM-MD5 I1030 05:54:04.527649 29516 authenticatee.hpp:250] Attempting to authenticate with mechanism 'CRAM-MD5' I1030 05:54:04.527742 29516 authenticator.hpp:267] Received SASL authentication start I1030 05:54:04.527794 29516 authenticator.hpp:389] Authentication requires more steps I1030 05:54:04.527885 29516 authenticatee.hpp:270] Received SASL authentication step I1030 05:54:04.527986 29516 authenticator.hpp:295] Received SASL authentication step I1030 05:54:04.528019 29516 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 I1030 05:54:04.528034 29516 auxprop.cpp:153] Looking up auxiliary property '*userPassword' I1030 05:54:04.528065 29516 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I1030 05:54:04.528090 29516 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 I1030 05:54:04.528101 29516 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I1030 05:54:04.528110 29516 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I1030 05:54:04.529158 29524 log.cpp:680] Attempting to append 316 bytes to the log I1030 05:54:04.545205 29511 slave.cpp:1050] Will retry registration in 50.72335ms if necessary I1030 05:54:04.545310 29519 master.cpp:3020] Ignoring register slave message from slave(27)@67.195.81.187:54775 (pomona.apache.org) as admission is already in progress I1030 05:54:05.499511 29514 hierarchical_allocator_process.hpp:697] No resources available to allocate! I1030 05:54:07.770174 29516 authenticator.hpp:381] Authentication success I1030 05:54:07.770304 29514 hierarchical_allocator_process.hpp:659] Performed allocation for 0 slaves in 2.270803805secs I1030 05:54:07.770408 29521 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3 I1030 05:54:07.770439 29512 authenticatee.hpp:310] Authentication success I1030 05:54:07.770506 29515 master.cpp:3893] Successfully authenticated principal 'test-principal' at [email protected]:54775 I1030 05:54:07.770843 29512 sched.cpp:357] Successfully authenticated with master [email protected]:54775 I1030 05:54:07.770891 29512 sched.cpp:476] Sending registration request to [email protected]:54775 I1030 05:54:07.771092 29515 master.cpp:1362] Received registration request for framework 'default' at [email protected]:54775 I1030 05:54:07.771183 29515 master.cpp:1321] Authorizing framework principal 'test-principal' to receive offers for role '*' I1030 05:54:07.771579 29512 replica.cpp:508] Replica received write request for position 3 I1030 05:54:07.771793 29512 leveldb.cpp:343] Persisting action (335 bytes) to leveldb took 173691ns I1030 05:54:07.771795 29524 master.cpp:1426] Registering framework 20141030-055359-3142697795-54775-29497-0000 (default) at [email protected]:54775 I1030 05:54:07.771822 29512 replica.cpp:676] Persisted action at 3 I1030 05:54:07.772176 29512 hierarchical_allocator_process.hpp:329] Added framework 20141030-055359-3142697795-54775-29497-0000 I1030 05:54:07.772207 29512 hierarchical_allocator_process.hpp:697] No resources available to allocate! I1030 05:54:07.772220 29512 hierarchical_allocator_process.hpp:659] Performed allocation for 0 slaves in 19422ns I1030 05:54:07.772459 29526 sched.cpp:407] Framework registered with 20141030-055359-3142697795-54775-29497-0000 I1030 05:54:07.772558 29526 sched.cpp:421] Scheduler::registered took 65296ns I1030 05:54:07.772671 29524 replica.cpp:655] Replica received learned notice for position 3 I1030 05:54:07.773195 29524 leveldb.cpp:343] Persisting action (337 bytes) to leveldb took 495300ns I1030 05:54:07.773221 29524 replica.cpp:676] Persisted action at 3 I1030 05:54:07.773244 29524 replica.cpp:661] Replica learned APPEND action at position 3 I1030 05:54:07.774744 29516 registrar.cpp:490] Successfully updated the 'registry' in 3.248780032secs I1030 05:54:07.775080 29523 log.cpp:699] Attempting to truncate the log to 3 I1030 05:54:07.775238 29520 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4 I1030 05:54:07.775401 29523 slave.cpp:2522] Received ping from slave-observer(25)@67.195.81.187:54775 I1030 05:54:07.775495 29519 master.cpp:3086] Registered slave 20141030-055359-3142697795-54775-29497-S0 at slave(27)@67.195.81.187:54775 (pomona.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] I1030 05:54:07.775574 29523 slave.cpp:756] Registered with master [email protected]:54775; given slave ID 20141030-055359-3142697795-54775-29497-S0 I1030 05:54:07.775686 29515 status_update_manager.cpp:178] Resuming sending status updates I1030 05:54:07.775676 29526 hierarchical_allocator_process.hpp:442] Added slave 20141030-055359-3142697795-54775-29497-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) I1030 05:54:07.775938 29526 hierarchical_allocator_process.hpp:734] Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20141030-055359-3142697795-54775-29497-S0 to framework 20141030-055359-3142697795-54775-29497-0000 I1030 05:54:07.776259 29517 replica.cpp:508] Replica received write request for position 4 I1030 05:54:07.776388 29526 hierarchical_allocator_process.hpp:679] Performed allocation for slave 20141030-055359-3142697795-54775-29497-S0 in 627202ns I1030 05:54:07.776723 29517 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 403977ns I1030 05:54:07.776726 29514 master.cpp:3795] Sending 1 offers to framework 20141030-055359-3142697795-54775-29497-0000 (default) at [email protected]:54775 I1030 05:54:07.776757 29517 replica.cpp:676] Persisted action at 4 I1030 05:54:07.777396 29525 replica.cpp:655] Replica received learned notice for position 4 I1030 05:54:07.777694 29524 sched.cpp:544] Scheduler::resourceOffers took 534035ns I1030 05:54:07.777719 29525 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 295210ns I1030 05:54:07.777772 29525 leveldb.cpp:401] Deleting ~2 keys from leveldb took 27312ns I1030 05:54:07.777791 29525 replica.cpp:676] Persisted action at 4 I1030 05:54:07.777813 29525 replica.cpp:661] Replica learned TRUNCATE action at position 4 I1030 05:54:07.778673 29519 master.cpp:2321] Processing reply for offers: [ 20141030-055359-3142697795-54775-29497-O0 ] on slave 20141030-055359-3142697795-54775-29497-S0 at slave(27)@67.195.81.187:54775 (pomona.apache.org) for framework 20141030-055359-3142697795-54775-29497-0000 (default) at [email protected]:54775 W1030 05:54:07.778784 29519 master.cpp:1969] Executor default for task 0 uses less CPUs (None) than the minimum required (0.01). Please update your executor, as this will be mandatory in future releases. W1030 05:54:07.778818 29519 master.cpp:1980] Executor default for task 0 uses less memory (None) than the minimum required (32MB). Please update your executor, as this will be mandatory in future releases. I1030 05:54:07.778919 29519 master.cpp:2417] Authorizing framework principal 'test-principal' to launch task 0 as user 'jenkins' I1030 05:54:07.779989 29512 master.hpp:877] Adding task 0 with resources cpus(*):1; mem(*):512 on slave 20141030-055359-3142697795-54775-29497-S0 (pomona.apache.org) I1030 05:54:07.780067 29512 master.cpp:2480] Launching task 0 of framework 20141030-055359-3142697795-54775-29497-0000 (default) at [email protected]:54775 with resources cpus(*):1; mem(*):512 on slave 20141030-055359-3142697795-54775-29497-S0 at slave(27)@67.195.81.187:54775 (pomona.apache.org) I1030 05:54:07.780411 29521 slave.cpp:1081] Got assigned task 0 for framework 20141030-055359-3142697795-54775-29497-0000 I1030 05:54:07.780939 29518 hierarchical_allocator_process.hpp:563] Recovered cpus(*):1; mem(*):512; disk(*):1024; ports(*):[31000-32000] (total allocatable: cpus(*):1; mem(*):512; disk(*):1024; ports(*):[31000-32000]) on slave 20141030-055359-3142697795-54775-29497-S0 from framework 20141030-055359-3142697795-54775-29497-0000 I1030 05:54:07.780995 29521 slave.cpp:1191] Launching task 0 for framework 20141030-055359-3142697795-54775-29497-0000 I1030 05:54:07.780998 29518 hierarchical_allocator_process.hpp:599] Framework 20141030-055359-3142697795-54775-29497-0000 filtered slave 20141030-055359-3142697795-54775-29497-S0 for 5secs Itests/reconciliation_tests.cpp:112: Failure Failed to wait 10secs for update tests/reconciliation_tests.cpp:104: Failure Actual function call count doesn't match EXPECT_CALL(sched, statusUpdate(&driver, _))... Expected: to be called once 1030 05:54:07.783726 29521 slave.cpp:3871] Launching executor default of framework 20141030-055359-3142697795-54775-29497-0000 in work directory '/tmp/ReconciliationTest_TaskStateMismatch_jXTxgL/slaves/20141030-055359-3142697795-54775-29497-S0/frameworks/20141030-055359-3142697795-54775-29497-0000/executors/default/runs/f62d63de-e21a-438c-917d-ca4b61c34519' Actual: never called - unsatisfied and active I1030 05:54:08.771411 29516 hierarchical_allocator_process.hpp:816] Filtered cpus(*):1; mem(*):512; disk(*):1024; ports(*):[31000-32000] on slave 20141030-055359-3142697795-54775-29497-S0 for framework 20141030-055359-3142697795-54775-29497-0000 I1030 05:54:09.499510 29514 master.cpp:120] No whitelist given. Advertising offers for all slaves I1030 05:54:17.775676 29526 master.cpp:768] Framework 20141030-055359-3142697795-54775-29497-0000 (default) at [email protected]:54775 disconnected I1030 05:54:20.124783 29516 hierarchical_allocator_process.hpp:659] Performed allocation for 1 slaves in 11.353661562secs I1030 05:54:20.124831 29526 master.cpp:1731] Disconnecting framework 20141030-055359-3142697795-54775-29497-0000 (default) at [email protected]:54775 tests/reconciliation_tests.cpp:100: Failure Actual function call count doesn't match EXPECT_CALL(exec, launchTask(_, _))... Expected: to be called once Actual: never called - unsatisfied and active tests/reconciliation_tests.cpp:98: Failure Actual function call count doesn't match EXPECT_CALL(exec, registered(_, _, _, _))... Expected: to be called once Actual: never called - unsatisfied and active I1030 05:54:20.124938 29526 master.cpp:1747] Deactivating framework 20141030-055359-3142697795-54775-29497-0000 (default) at [email protected]:54775 F1030 05:54:20.124938 29521 logging.cpp:57] RAW: Pure virtual method called I1030 05:54:20.125049 29526 master.cpp:790] Giving framework 20141030-055359-3142697795-54775-29497-0000 (default) at [email protected]:54775 0ns to failover I1030 05:54:20.125176 29516 hierarchical_allocator_process.hpp:405] Deactivated framework 20141030-055359-3142697795-54775-29497-0000 I1030 05:54:20.125305 29515 master.cpp:3665] Framework failover timeout, removing framework 20141030-055359-3142697795-54775-29497-0000 (default) at [email protected]:54775 I1030 05:54:20.125332 29515 master.cpp:4201] Removing framework 20141030-055359-3142697795-54775-29497-0000 (default) at [email protected]:54775 I1030 05:54:20.127970 29515 master.cpp:4617] Updating the latest state of task 0 of framework 20141030-055359-3142697795-54775-29497-0000 to TASK_KILLED I1030 05:54:20.128203 29515 master.cpp:4676] Removing task 0 with resources cpus(*):1; mem(*):512 of framework 20141030-055359-3142697795-54775-29497-0000 on slave 20141030-055359-3142697795-54775-29497-S0 at slave(27)@67.195.81.187:54775 (pomona.apache.org) I1030 05:54:20.128458 29520 hierarchical_allocator_process.hpp:563] Recovered cpus(*):1; mem(*):512 (total allocatable: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) on slave 20141030-055359-3142697795-54775-29497-S0 from framework 20141030-055359-3142697795-54775-29497-0000 I1030 05:54:20.128635 29515 master.cpp:4705] Removing executor 'default' with resources of framework 20141030-055359-3142697795-54775-29497-0000 on slave 20141030-055359-3142697795-54775-29497-S0 at slave(27)@67.195.81.187:54775 (pomona.apache.org) I1030 05:54:20.129112 29515 master.cpp:677] Master terminating I1030 05:54:20.129189 29523 hierarchical_allocator_process.hpp:360] Removed framework 20141030-055359-3142697795-54775-29497-0000 [ FAILED ] ReconciliationTest.TaskStateMismatch (21026 ms) [ RUN ] ReconciliationTest.UnknownSlave Using temporary directory '/tmp/ReconciliationTest_UnknownSlave_sz29uu' @ 0x2adeb902ca8e google::LogMessage::Fail() @ 0x2adeb9032182 google::RawLog__() I1030 05:54:20.137413 29497 leveldb.cpp:176] Opened db in 2.509172ms I1030 05:54:20.138386 29497 leveldb.cpp:183] Compacted db in 938375ns I1030 05:54:20.138420 29497 leveldb.cpp:198] Created db iterator in 7060ns I1030 05:54:20.138438 29497 leveldb.cpp:204] Seeked to beginning of db in 1280ns I1030 05:54:20.138449 29497 leveldb.cpp:273] Iterated through 0 keys in the db in 630ns @ 0x2adeb86bfb86 __cxa_pure_virtual I1030 05:54:22.333158 29497 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I1030 05:54:22.334003 29517 recover.cpp:437] Starting replica recovery I1030 05:54:22.334370 29517 recover.cpp:463] Replica is in EMPTY status I1030 05:54:22.336093 29515 replica.cpp:638] Replica in EMPTY status received a broadcasted recover request I1030 05:54:22.336302 29526 recover.cpp:188] Received a recover response from a replica in EMPTY status I1030 05:54:22.336704 29524 recover.cpp:554] Updating replica status to STARTING I1030 05:54:22.337630 29522 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 737us I1030 05:54:22.337677 29522 replica.cpp:320] Persisted replica status to STARTING I1030 05:54:22.337810 29526 master.cpp:312] Master 20141030-055422-3142697795-54775-29497 (pomona.apache.org) started on 67.195.81.187:54775 I1030 05:54:22.337862 29526 master.cpp:358] Master only allowing authenticated frameworks to register I1030 05:54:22.337878 29526 master.cpp:363] Master only allowing authenticated slaves to register I1030 05:54:22.337898 29526 credentials.hpp:36] Loading credentials for authentication from '/tmp/ReconciliationTest_UnknownSlave_sz29uu/credentials' I1030 05:54:22.338032 29516 recover.cpp:463] Replica is in STARTING status I1030 05:54:22.338163 29526 master.cpp:392] Authorization enabled @ 0x2adeb89807bd mesos::internal::slave::Framework::launchExecutor() I1030 05:54:22.338692 29515 master.cpp:120] No whitelist given. Advertising offers for all slaves I1030 05:54:22.339212 29519 hierarchical_allocator_process.hpp:299] Initializing hierarchical allocator process with master : [email protected]:54775 I1030 05:54:22.339202 29522 replica.cpp:638] Replica in STARTING status received a broadcasted recover request I1030 05:54:22.339773 29514 recover.cpp:188] Received a recover response from a replica in STARTING status I1030 05:54:22.339844 29520 master.cpp:1242] The newly elected leader is [email protected]:54775 with id 20141030-055422-3142697795-54775-29497 I1030 05:54:22.339879 29520 master.cpp:1255] Elected as the leading master! I1030 05:54:22.339900 29520 master.cpp:1073] Recovering from registrar I1030 05:54:22.340183 29515 registrar.cpp:313] Recovering registrar I1030 05:54:22.340446 29518 recover.cpp:554] Updating replica status to VOTING I1030 05:54:22.341236 29520 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 565518ns I1030 05:54:22.341262 29520 replica.cpp:320] Persisted replica status to VOTING I1030 05:54:22.341406 29520 recover.cpp:568] Successfully joined the Paxos group I1030 05:54:22.341653 29520 recover.cpp:452] Recover process terminated I1030 05:54:22.342217 29526 log.cpp:656] Attempting to start the writer @ 0x2adeb8968b5a mesos::internal::slave::Slave::_runTask() I1030 05:54:22.343890 29512 replica.cpp:474] Replica received implicit promise request with proposal 1 I1030 05:54:22.344487 29512 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 563202ns I1030 05:54:22.344512 29512 replica.cpp:342] Persisted promised to 1 @ 0x2adeb89a0a0b _ZZN7process8dispatchIN5mesos8internal5slave5SlaveERKNS_6FutureIbEERKNS1_13FrameworkInfoERKNS1_11FrameworkIDERKSsRKNS1_8TaskInfoES6_S9_SC_SsSH_EEvRKNS_3PIDIT_EEMSL_FvT0_T1_T2_T3_T4_ET5_T6_T7_T8_T9_ENKUlPNS_11ProcessBaseEE_clES12_ I1030 05:54:22.345145 29523 coordinator.cpp:230] Coordinator attemping to fill missing position I1030 05:54:22.346741 29520 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2 I1030 05:54:22.347309 29520 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 531407ns I1030 05:54:22.347337 29520 replica.cpp:676] Persisted action at 0 I1030 05:54:22.348525 29522 replica.cpp:508] Replica received write request for position 0 I1030 05:54:22.348575 29522 leveldb.cpp:438] Reading position from leveldb took 24419ns I1030 05:54:22.349072 29522 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 463209ns I @ 0x2adeb89c6fdd _ZNSt17_Function_handlerIFvPN7process11ProcessBaseEEZNS0_8dispatchIN5mesos8internal5slave5SlaveERKNS0_6FutureIbEERKNS5_13FrameworkInfoERKNS5_11FrameworkIDERKSsRKNS5_8TaskInfoESA_SD_SG_SsSL_EEvRKNS0_3PIDIT_EEMSP_FvT0_T1_T2_T3_T4_ET5_T6_T7_T8_T9_EUlS2_E_E9_M_invokeERKSt9_Any_dataS2_ 1030 05:54:22.349097 29522 replica.cpp:676] Persisted action at 0 I1030 05:54:22.643363 29524 replica.cpp:655] Replica received learned notice for position 0 I1030 05:54:22.644031 29524 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 626475ns I1030 05:54:22.644059 29524 replica.cpp:676] Persisted action at 0 I1030 05:54:22.644081 29524 replica.cpp:661] Replica learned NOP action at position 0 I1030 05:54:22.644937 29513 log.cpp:672] Writer started with ending position 0 I1030 05:54:22.646476 29522 leveldb.cpp:438] Reading position from leveldb took 29654ns @ 0x2adeb8fbe89f std::function<>::operator()() I1030 05:54:22.649744 29511 registrar.cpp:346] Successfully fetched the registry (0B) in 309.50912ms I1030 05:54:22.649865 29511 registrar.cpp:445] Applied 1 operations in 26852ns; attempting to update the 'registry' @ 0x2adeb8f9fb67 process::ProcessBase::visit() I1030 05:54:22.652909 29525 log.cpp:680] Attempting to append 139 bytes to the log I1030 05:54:22.653067 29512 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1 I1030 05:54:22.654033 29516 replica.cpp:508] Replica received write request for position 1 I1030 05:54:22.654588 29516 leveldb.cpp:343] Persisting action (158 bytes) to leveldb took 521467ns I1030 05:54:22.654619 29516 replica.cpp:676] Persisted action at 1 @ 0x2adeb8faa49c process::DispatchEvent::visit() I1030 05:54:22.655232 29514 replica.cpp:655] Replica received learned notice for position 1 I1030 05:54:22.655637 29514 leveldb.cpp:343] Persisting action (160 bytes) to leveldb took 378403ns I1030 05:54:22.655663 29514 replica.cpp:676] Persisted action at 1 I1030 05:54:22.655683 29514 replica.cpp:661] Replica learned APPEND action at position 1 I1030 05:54:22.656695 29523 registrar.cpp:490] Successfully updated the 'registry' in 6.767872ms I1030 05:54:22.656848 29523 registrar.cpp:376] Successfully recovered registrar I1030 05:54:22.656976 29518 log.cpp:699] Attempting to truncate the log to 1 @ 0x8f6fa2 process::ProcessBase::serve() I1030 05:54:22.657117 29511 master.cpp:1100] Recovered 0 slaves from the Registry (101B) ; allowing 10mins for slaves to re-register I1030 05:54:22.657215 29516 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2 I1030 05:54:22.658125 29516 replica.cpp:508] Replica received write request for position 2 I1030 05:54:22.658622 29516 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 462724ns I1030 05:54:22.658648 29516 replica.cpp:676] Persisted action at 2 I1030 05:54:22.659272 29514 replica.cpp:655] Replica received learned notice for position 2 I1030 05:54:22.659711 29514 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 395532ns I1030 05:54:22.659757 29514 leveldb.cpp:401] Deleting ~1 keys from leveldb took 22259ns I1030 05:54:22.659775 29514 replica.cpp:676] Persisted action at 2 I1030 05:54:22.659796 29514 replica.cpp:661] Replica learned TRUNCATE action at position 2 @ 0x2adeb8f9bddc process::ProcessManager::resume() @ 0x2adeb8f924a1 process::schedule() @ 0x2adebb2f0182 start_thread @ 0x2adebb600fbd (unknown) make[3]: *** [check-local] Aborted make[3]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/ws/src'> make[2]: *** [check-am] Error 2 make[2]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/ws/src'> make[1]: *** [check] Error 2 make[1]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/ws/src'> make: *** [check-recursive] Error 1 Test finished Exit status: 2 Build step 'Execute shell' marked build as failure Recording test results
