Just pushed the fix.
On Wed, Apr 30, 2014 at 8:31 AM, Benjamin Mahler <[email protected]>wrote: > Thanks for digging in Adam! I will get this fixed. > > > On Wed, Apr 30, 2014 at 12:29 AM, Adam Bordelon <[email protected]>wrote: > >> This is dying inside the first line of RetrySlaveAuthenticationTest, >> which is a default StartMaster() call with default master flags. >> StartMaster/start FATALs while waiting for Master::_recover, after >> spawning the new Master process. >> This await(_recover) dates back to bmahler's LogStorage commit >> 7bf1e8a6b6d1160c65d37a03f38341604a122078 on April 16. >> The logs show the master started, "Successfully recovered registrar", and >> "Recovered 0 slaves from the Registry (99B) ; allowing 10mins for slaves to >> re-register" all at 06:08:49.5 (slightly more than 10s before the >> await(_recover) failure). The latter log message is actually logged from >> _recover, so we know Master actually called _recover. >> (TL;DR) Perhaps the FUTURE_DISPATCH(_recover) call in >> Cluster::Masters::start() should be before process::spawn(master.master), >> in case Master initializes/recovers too quickly and FUTURE_DISPATCH loses >> the race? >> >> -A- >> >> >> On Tue, Apr 29, 2014 at 11:26 PM, Vinod Kone <[email protected]> wrote: >> >>> hey adam can you triage this? >>> >>> >>> On Tue, Apr 29, 2014 at 11:09 PM, Apache Jenkins Server < >>> [email protected]> wrote: >>> >>>> See < >>>> https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/2101/changes >>>> > >>>> >>>> Changes: >>>> >>>> [vinod] Fixed distclean break during maven clean up. >>>> >>>> [idownes] Fixed some indentation. >>>> >>>> [benjamin.hindman] Better error message for protobuf::write. >>>> >>>> [benjamin.hindman] Added 'mesos-usage' for use by external >>>> containerizers. >>>> >>>> [benjamin.hindman] Added test for slave stopping before containerizer >>>> launches. >>>> >>>> [benjamin.hindman] Allowed passing headers to http::get/post. >>>> >>>> [benjamin.hindman] Updated uses of http::post. >>>> >>>> [benjamin.hindman] Used memory::shared_ptr instead of boost::shared_ptr. >>>> >>>> [benjamin.hindman] Added 'cref' and 'ref' to lambda:: namespace. >>>> >>>> [benjamin.hindman] Added process::async overloads for void functions. >>>> >>>> ------------------------------------------ >>>> [...truncated 25160 lines...] >>>> W0430 06:08:49.430877 30345 slave.cpp:2154] Master disconnected! >>>> Waiting for a new master to be elected >>>> I0430 06:08:49.431460 30344 replica.cpp:643] Replica received learned >>>> notice for position 4 >>>> I0430 06:08:49.432160 30344 leveldb.cpp:341] Persisting action (18 >>>> bytes) to leveldb took 675495ns >>>> I0430 06:08:49.432185 30344 leveldb.cpp:399] Deleting ~2 keys from >>>> leveldb took 14255ns >>>> I0430 06:08:49.432194 30344 replica.cpp:664] Persisted action at 4 >>>> I0430 06:08:49.432204 30344 replica.cpp:649] Replica learned TRUNCATE >>>> action at position 4 >>>> I0430 06:08:49.433727 30322 slave.cpp:414] Slave terminating >>>> [ OK ] AuthenticationTest.LeaderElectionDuringSlaveAuthentication >>>> (61 ms) >>>> [ RUN ] AuthenticationTest.LeaderElection >>>> I0430 06:08:49.441107 30322 leveldb.cpp:174] Opened db in 2.896681ms >>>> I0430 06:08:49.441488 30322 leveldb.cpp:181] Compacted db in 258457ns >>>> I0430 06:08:49.441550 30322 leveldb.cpp:196] Created db iterator in >>>> 4261ns >>>> I0430 06:08:49.441604 30322 leveldb.cpp:202] Seeked to beginning of db >>>> in 638ns >>>> I0430 06:08:49.441655 30322 leveldb.cpp:271] Iterated through 0 keys in >>>> the db in 620ns >>>> I0430 06:08:49.441715 30322 replica.cpp:729] Replica recovered with log >>>> positions 0 -> 0 with 1 holes and 0 unlearned >>>> I0430 06:08:49.442021 30349 recover.cpp:425] Starting replica recovery >>>> I0430 06:08:49.442101 30349 recover.cpp:451] Replica is in EMPTY status >>>> I0430 06:08:49.442471 30349 replica.cpp:626] Replica in EMPTY status >>>> received a broadcasted recover request >>>> I0430 06:08:49.442528 30349 recover.cpp:188] Received a recover >>>> response from a replica in EMPTY status >>>> I0430 06:08:49.442637 30349 recover.cpp:542] Updating replica status to >>>> STARTING >>>> I0430 06:08:49.443323 30349 leveldb.cpp:304] Persisting metadata (8 >>>> bytes) to leveldb took 613124ns >>>> I0430 06:08:49.443336 30349 replica.cpp:320] Persisted replica status >>>> to STARTING >>>> I0430 06:08:49.443397 30349 recover.cpp:451] Replica is in STARTING >>>> status >>>> I0430 06:08:49.443672 30349 replica.cpp:626] Replica in STARTING status >>>> received a broadcasted recover request >>>> I0430 06:08:49.443718 30349 recover.cpp:188] Received a recover >>>> response from a replica in STARTING status >>>> I0430 06:08:49.443810 30349 recover.cpp:542] Updating replica status to >>>> VOTING >>>> I0430 06:08:49.443953 30349 leveldb.cpp:304] Persisting metadata (8 >>>> bytes) to leveldb took 100071ns >>>> I0430 06:08:49.443964 30349 replica.cpp:320] Persisted replica status >>>> to VOTING >>>> I0430 06:08:49.443995 30349 recover.cpp:556] Successfully joined the >>>> Paxos group >>>> I0430 06:08:49.444046 30349 recover.cpp:440] Recover process terminated >>>> I0430 06:08:49.444860 30347 master.cpp:266] Master >>>> 20140430-060849-143311683-58511-30322 (minerva.apache.org) started on >>>> 67.195.138.8:58511 >>>> I0430 06:08:49.444880 30347 master.cpp:303] Master only allowing >>>> authenticated frameworks to register >>>> I0430 06:08:49.444885 30347 master.cpp:308] Master only allowing >>>> authenticated slaves to register >>>> I0430 06:08:49.444890 30347 credentials.hpp:35] Loading credentials for >>>> authentication >>>> W0430 06:08:49.444926 30347 credentials.hpp:48] Failed to stat >>>> credentials file >>>> 'file:///tmp/AuthenticationTest_LeaderElection_2EYXk0/credentials': No such >>>> file or directory >>>> I0430 06:08:49.445458 30347 hierarchical_allocator_process.hpp:302] >>>> Initializing hierarchical allocator process with master : >>>> [email protected]:58511 >>>> I0430 06:08:49.445492 30347 master.cpp:104] No whitelist given. >>>> Advertising offers for all slaves >>>> I0430 06:08:49.445680 30347 master.cpp:922] The newly elected leader is >>>> [email protected]:58511 with id 20140430-060849-143311683-58511-30322 >>>> I0430 06:08:49.445688 30347 master.cpp:932] Elected as the leading >>>> master! >>>> I0430 06:08:49.445695 30347 master.cpp:753] Recovering from registrar >>>> I0430 06:08:49.445749 30347 registrar.cpp:275] Recovering registrar >>>> I0430 06:08:49.445976 30347 log.cpp:656] Attempting to start the writer >>>> I0430 06:08:49.446288 30347 replica.cpp:474] Replica received implicit >>>> promise request with proposal 1 >>>> I0430 06:08:49.446410 30347 leveldb.cpp:304] Persisting metadata (8 >>>> bytes) to leveldb took 111558ns >>>> I0430 06:08:49.446423 30347 replica.cpp:342] Persisted promised to 1 >>>> I0430 06:08:49.446666 30347 coordinator.cpp:229] Coordinator attemping >>>> to fill missing position >>>> I0430 06:08:49.447002 30347 replica.cpp:375] Replica received explicit >>>> promise request for position 0 with proposal 2 >>>> I0430 06:08:49.447116 30347 leveldb.cpp:341] Persisting action (8 >>>> bytes) to leveldb took 102007ns >>>> I0430 06:08:49.447127 30347 replica.cpp:664] Persisted action at 0 >>>> I0430 06:08:49.447392 30347 replica.cpp:508] Replica received write >>>> request for position 0 >>>> I0430 06:08:49.447412 30347 leveldb.cpp:436] Reading position from >>>> leveldb took 11518ns >>>> I0430 06:08:49.453721 30347 leveldb.cpp:341] Persisting action (14 >>>> bytes) to leveldb took 6.293392ms >>>> I0430 06:08:49.453747 30347 replica.cpp:664] Persisted action at 0 >>>> I0430 06:08:49.453896 30347 replica.cpp:643] Replica received learned >>>> notice for position 0 >>>> I0430 06:08:49.454051 30347 leveldb.cpp:341] Persisting action (16 >>>> bytes) to leveldb took 141267ns >>>> I0430 06:08:49.454069 30347 replica.cpp:664] Persisted action at 0 >>>> I0430 06:08:49.454080 30347 replica.cpp:649] Replica learned NOP action >>>> at position 0 >>>> I0430 06:08:49.454254 30346 log.cpp:672] Writer started with ending >>>> position 0 >>>> I0430 06:08:49.454620 30346 leveldb.cpp:436] Reading position from >>>> leveldb took 10194ns >>>> I0430 06:08:49.455654 30346 registrar.cpp:308] Successfully recovered >>>> registrar >>>> I0430 06:08:49.455674 30346 registrar.cpp:379] Attempting to update the >>>> 'registry' >>>> I0430 06:08:49.456663 30346 log.cpp:680] Attempting to append 137 bytes >>>> to the log >>>> I0430 06:08:49.456706 30346 coordinator.cpp:339] Coordinator attempting >>>> to write APPEND action at position 1 >>>> I0430 06:08:49.456913 30346 replica.cpp:508] Replica received write >>>> request for position 1 >>>> I0430 06:08:49.457074 30346 leveldb.cpp:341] Persisting action (156 >>>> bytes) to leveldb took 150036ns >>>> I0430 06:08:49.457087 30346 replica.cpp:664] Persisted action at 1 >>>> I0430 06:08:49.457414 30348 replica.cpp:643] Replica received learned >>>> notice for position 1 >>>> I0430 06:08:49.457545 30348 leveldb.cpp:341] Persisting action (158 >>>> bytes) to leveldb took 111489ns >>>> I0430 06:08:49.457556 30348 replica.cpp:664] Persisted action at 1 >>>> I0430 06:08:49.457563 30348 replica.cpp:649] Replica learned APPEND >>>> action at position 1 >>>> I0430 06:08:49.457769 30348 registrar.cpp:427] Successfully updated >>>> 'registry' >>>> I0430 06:08:49.457866 30343 log.cpp:699] Attempting to truncate the log >>>> to 1 >>>> I0430 06:08:49.457866 30348 master.cpp:780] Recovered 0 slaves from the >>>> Registry (99B) ; allowing 10mins for slaves to re-register >>>> I0430 06:08:49.457913 30348 coordinator.cpp:339] Coordinator attempting >>>> to write TRUNCATE action at position 2 >>>> I0430 06:08:49.458087 30348 replica.cpp:508] Replica received write >>>> request for position 2 >>>> I0430 06:08:49.458184 30348 leveldb.cpp:341] Persisting action (16 >>>> bytes) to leveldb took 83654ns >>>> I0430 06:08:49.458195 30348 replica.cpp:664] Persisted action at 2 >>>> I0430 06:08:49.458333 30348 replica.cpp:643] Replica received learned >>>> notice for position 2 >>>> I0430 06:08:49.458415 30348 leveldb.cpp:341] Persisting action (18 >>>> bytes) to leveldb took 73068ns >>>> I0430 06:08:49.458441 30348 leveldb.cpp:399] Deleting ~1 keys from >>>> leveldb took 13141ns >>>> I0430 06:08:49.458451 30348 replica.cpp:664] Persisted action at 2 >>>> I0430 06:08:49.458457 30348 replica.cpp:649] Replica learned TRUNCATE >>>> action at position 2 >>>> I0430 06:08:49.459568 30322 sched.cpp:121] Version: 0.19.0 >>>> I0430 06:08:49.459725 30348 sched.cpp:217] New master detected at >>>> [email protected]:58511 >>>> I0430 06:08:49.459740 30348 sched.cpp:268] Authenticating with master >>>> [email protected]:58511 >>>> I0430 06:08:49.459815 30348 authenticatee.hpp:128] Creating new client >>>> SASL connection >>>> I0430 06:08:49.459944 30348 master.cpp:2795] Authenticating >>>> scheduler(74)@67.195.138.8:58511 >>>> >>>> I0430 06:08:49.460014 30348 authenticator.hpp:148] Creating new server >>>> SASL connection >>>> I0430 06:08:49.460100 30348 authenticatee.hpp:219] Received SASL >>>> authentication mechanisms: CRAM-MD5 >>>> I0430 06:08:49.460115 30348 authenticatee.hpp:245] Attempting to >>>> authenticate with mechanism 'CRAM-MD5' >>>> I0430 06:08:49.460139 30348 authenticator.hpp:254] Received SASL >>>> authentication start >>>> I0430 06:08:49.460167 30348 authenticator.hpp:342] Authentication >>>> requires more steps >>>> I0430 06:08:49.463879 30348 sched.cpp:217] New master detected at >>>> [email protected]:58511 >>>> I0430 06:08:49.463973 30348 sched.cpp:323] Failed to authenticate with >>>> master [email protected]:58511: master changed >>>> I0430 06:08:49.463994 30348 sched.cpp:268] Authenticating with master >>>> [email protected]:58511 >>>> I0430 06:08:49.464052 30348 authenticatee.hpp:128] Creating new client >>>> SASL connection >>>> W0430 06:08:49.464123 30348 master.cpp:2830] Failed to authenticate >>>> scheduler(74)@67.195.138.8:58511: Failed to communicate with >>>> authenticatee >>>> I0430 06:08:49.464177 30348 master.cpp:2795] Authenticating >>>> scheduler(74)@67.195.138.8:58511 >>>> >>>> I0430 06:08:49.464236 30348 authenticator.hpp:148] Creating new server >>>> SASL connection >>>> I0430 06:08:49.464301 30348 authenticatee.hpp:219] Received SASL >>>> authentication mechanisms: CRAM-MD5 >>>> I0430 06:08:49.464314 30348 authenticatee.hpp:245] Attempting to >>>> authenticate with mechanism 'CRAM-MD5' >>>> I0430 06:08:49.464335 30348 authenticator.hpp:254] Received SASL >>>> authentication start >>>> I0430 06:08:49.464359 30348 authenticator.hpp:342] Authentication >>>> requires more steps >>>> I0430 06:08:49.464380 30348 authenticatee.hpp:265] Received SASL >>>> authentication step >>>> I0430 06:08:49.464416 30348 authenticator.hpp:282] Received SASL >>>> authentication step >>>> I0430 06:08:49.464432 30348 auxprop.cpp:81] Request to lookup >>>> properties for user: 'test-principal' realm: 'minerva.apache.org' >>>> server FQDN: 'minerva.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: >>>> false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false >>>> I0430 06:08:49.464438 30348 auxprop.cpp:153] Looking up auxiliary >>>> property '*userPassword' >>>> I0430 06:08:49.464450 30348 auxprop.cpp:153] Looking up auxiliary >>>> property '*cmusaslsecretCRAM-MD5' >>>> I0430 06:08:49.464459 30348 auxprop.cpp:81] Request to lookup >>>> properties for user: 'test-principal' realm: 'minerva.apache.org' >>>> server FQDN: 'minerva.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: >>>> false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true >>>> I0430 06:08:49.464465 30348 auxprop.cpp:103] Skipping auxiliary >>>> property '*userPassword' since SASL_AUXPROP_AUTHZID == true >>>> I0430 06:08:49.464472 30348 auxprop.cpp:103] Skipping auxiliary >>>> property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true >>>> I0430 06:08:49.464483 30348 authenticator.hpp:334] Authentication >>>> success >>>> I0430 06:08:49.464504 30348 authenticatee.hpp:305] Authentication >>>> success >>>> I0430 06:08:49.464522 30348 master.cpp:2835] Successfully authenticated >>>> scheduler(74)@67.195.138.8:58511 >>>> I0430 06:08:49.464570 30348 sched.cpp:342] Successfully authenticated >>>> with master [email protected]:58511 >>>> I0430 06:08:49.464581 30348 sched.cpp:461] Sending registration request >>>> to [email protected]:58511 >>>> I0430 06:08:49.464622 30348 master.cpp:981] Received registration >>>> request from scheduler(74)@67.195.138.8:58511 >>>> I0430 06:08:49.464647 30348 master.cpp:999] Registering framework >>>> 20140430-060849-143311683-58511-30322-0000 at scheduler(74)@ >>>> 67.195.138.8:58511 >>>> >>>> I0430 06:08:49.464697 30348 sched.cpp:392] Framework registered with >>>> 20140430-060849-143311683-58511-30322-0000 >>>> I0430 06:08:49.464718 30348 sched.cpp:406] Scheduler::registered took >>>> 12387ns >>>> I0430 06:08:49.464759 30348 hierarchical_allocator_process.hpp:332] >>>> Added framework 20140430-060849-143311683-58511-30322-0000 >>>> I0430 06:08:49.464769 30348 hierarchical_allocator_process.hpp:726] No >>>> resources available to allocate! >>>> I0430 06:08:49.464776 30348 hierarchical_allocator_process.hpp:688] >>>> Performed allocation for 0 slaves in 7440ns >>>> I0430 06:08:49.464843 30322 master.cpp:551] Master terminating >>>> I0430 06:08:49.464926 30345 sched.cpp:731] Stopping framework >>>> '20140430-060849-143311683-58511-30322-0000' >>>> [ OK ] AuthenticationTest.LeaderElection (31 ms) >>>> [ RUN ] AuthenticationTest.RetrySlaveAuthentication >>>> I0430 06:08:49.498736 30322 leveldb.cpp:174] Opened db in 27.688285ms >>>> I0430 06:08:49.499557 30322 leveldb.cpp:181] Compacted db in 770486ns >>>> I0430 06:08:49.499634 30322 leveldb.cpp:196] Created db iterator in >>>> 6638ns >>>> I0430 06:08:49.499686 30322 leveldb.cpp:202] Seeked to beginning of db >>>> in 683ns >>>> I0430 06:08:49.499735 30322 leveldb.cpp:271] Iterated through 0 keys in >>>> the db in 677ns >>>> I0430 06:08:49.499804 30322 replica.cpp:729] Replica recovered with log >>>> positions 0 -> 0 with 1 holes and 0 unlearned >>>> I0430 06:08:49.500140 30349 recover.cpp:425] Starting replica recovery >>>> I0430 06:08:49.500231 30349 recover.cpp:451] Replica is in EMPTY status >>>> I0430 06:08:49.500625 30349 replica.cpp:626] Replica in EMPTY status >>>> received a broadcasted recover request >>>> I0430 06:08:49.500684 30349 recover.cpp:188] Received a recover >>>> response from a replica in EMPTY status >>>> I0430 06:08:49.500798 30349 recover.cpp:542] Updating replica status to >>>> STARTING >>>> I0430 06:08:49.501648 30349 leveldb.cpp:304] Persisting metadata (8 >>>> bytes) to leveldb took 791660ns >>>> I0430 06:08:49.501662 30349 replica.cpp:320] Persisted replica status >>>> to STARTING >>>> I0430 06:08:49.501721 30349 recover.cpp:451] Replica is in STARTING >>>> status >>>> I0430 06:08:49.501999 30349 replica.cpp:626] Replica in STARTING status >>>> received a broadcasted recover request >>>> I0430 06:08:49.502045 30349 recover.cpp:188] Received a recover >>>> response from a replica in STARTING status >>>> I0430 06:08:49.502137 30349 recover.cpp:542] Updating replica status to >>>> VOTING >>>> I0430 06:08:49.502284 30349 leveldb.cpp:304] Persisting metadata (8 >>>> bytes) to leveldb took 104244ns >>>> I0430 06:08:49.502295 30349 replica.cpp:320] Persisted replica status >>>> to VOTING >>>> I0430 06:08:49.502326 30349 recover.cpp:556] Successfully joined the >>>> Paxos group >>>> I0430 06:08:49.502378 30349 recover.cpp:440] Recover process terminated >>>> I0430 06:08:49.503067 30349 master.cpp:266] Master >>>> 20140430-060849-143311683-58511-30322 (minerva.apache.org) started on >>>> 67.195.138.8:58511 >>>> I0430 06:08:49.503084 30349 master.cpp:303] Master only allowing >>>> authenticated frameworks to register >>>> I0430 06:08:49.503090 30349 master.cpp:308] Master only allowing >>>> authenticated slaves to register >>>> I0430 06:08:49.503095 30349 credentials.hpp:35] Loading credentials for >>>> authentication >>>> W0430 06:08:49.503130 30349 credentials.hpp:48] Failed to stat >>>> credentials file >>>> 'file:///tmp/AuthenticationTest_RetrySlaveAuthentication_udJyoz/credentials': >>>> No such file or directory >>>> I0430 06:08:49.503645 30349 hierarchical_allocator_process.hpp:302] >>>> Initializing hierarchical allocator process with master : >>>> [email protected]:58511 >>>> I0430 06:08:49.503679 30349 master.cpp:104] No whitelist given. >>>> Advertising offers for all slaves >>>> I0430 06:08:49.503868 30349 master.cpp:922] The newly elected leader is >>>> [email protected]:58511 with id 20140430-060849-143311683-58511-30322 >>>> I0430 06:08:49.503876 30349 master.cpp:932] Elected as the leading >>>> master! >>>> I0430 06:08:49.503882 30349 master.cpp:753] Recovering from registrar >>>> I0430 06:08:49.503937 30349 registrar.cpp:275] Recovering registrar >>>> I0430 06:08:49.504156 30349 log.cpp:656] Attempting to start the writer >>>> I0430 06:08:49.504475 30349 replica.cpp:474] Replica received implicit >>>> promise request with proposal 1 >>>> I0430 06:08:49.504598 30349 leveldb.cpp:304] Persisting metadata (8 >>>> bytes) to leveldb took 111380ns >>>> I0430 06:08:49.504609 30349 replica.cpp:342] Persisted promised to 1 >>>> I0430 06:08:49.504770 30349 coordinator.cpp:229] Coordinator attemping >>>> to fill missing position >>>> I0430 06:08:49.505084 30349 replica.cpp:375] Replica received explicit >>>> promise request for position 0 with proposal 2 >>>> I0430 06:08:49.505182 30349 leveldb.cpp:341] Persisting action (8 >>>> bytes) to leveldb took 85434ns >>>> I0430 06:08:49.505192 30349 replica.cpp:664] Persisted action at 0 >>>> I0430 06:08:49.505431 30349 replica.cpp:508] Replica received write >>>> request for position 0 >>>> I0430 06:08:49.505450 30349 leveldb.cpp:436] Reading position from >>>> leveldb took 10523ns >>>> I0430 06:08:49.505548 30349 leveldb.cpp:341] Persisting action (14 >>>> bytes) to leveldb took 84781ns >>>> I0430 06:08:49.505558 30349 replica.cpp:664] Persisted action at 0 >>>> I0430 06:08:49.505684 30349 replica.cpp:643] Replica received learned >>>> notice for position 0 >>>> I0430 06:08:49.505836 30349 leveldb.cpp:341] Persisting action (16 >>>> bytes) to leveldb took 135965ns >>>> I0430 06:08:49.505846 30349 replica.cpp:664] Persisted action at 0 >>>> I0430 06:08:49.505853 30349 replica.cpp:649] Replica learned NOP action >>>> at position 0 >>>> I0430 06:08:49.505997 30349 log.cpp:672] Writer started with ending >>>> position 0 >>>> I0430 06:08:49.506242 30349 leveldb.cpp:436] Reading position from >>>> leveldb took 6183ns >>>> I0430 06:08:49.507227 30349 registrar.cpp:308] Successfully recovered >>>> registrar >>>> I0430 06:08:49.507243 30349 registrar.cpp:379] Attempting to update the >>>> 'registry' >>>> I0430 06:08:49.508235 30349 log.cpp:680] Attempting to append 137 bytes >>>> to the log >>>> I0430 06:08:49.508271 30349 coordinator.cpp:339] Coordinator attempting >>>> to write APPEND action at position 1 >>>> I0430 06:08:49.508438 30349 replica.cpp:508] Replica received write >>>> request for position 1 >>>> I0430 06:08:49.508555 30349 leveldb.cpp:341] Persisting action (156 >>>> bytes) to leveldb took 105618ns >>>> I0430 06:08:49.508610 30349 replica.cpp:664] Persisted action at 1 >>>> I0430 06:08:49.508999 30342 replica.cpp:643] Replica received learned >>>> notice for position 1 >>>> I0430 06:08:49.509121 30342 leveldb.cpp:341] Persisting action (158 >>>> bytes) to leveldb took 109883ns >>>> I0430 06:08:49.509132 30342 replica.cpp:664] Persisted action at 1 >>>> I0430 06:08:49.509140 30342 replica.cpp:649] Replica learned APPEND >>>> action at position 1 >>>> I0430 06:08:49.509374 30342 registrar.cpp:427] Successfully updated >>>> 'registry' >>>> I0430 06:08:49.509431 30342 log.cpp:699] Attempting to truncate the log >>>> to 1 >>>> I0430 06:08:49.509485 30342 master.cpp:780] Recovered 0 slaves from the >>>> Registry (99B) ; allowing 10mins for slaves to re-register >>>> I0430 06:08:49.509522 30342 coordinator.cpp:339] Coordinator attempting >>>> to write TRUNCATE action at position 2 >>>> I0430 06:08:49.509747 30349 replica.cpp:508] Replica received write >>>> request for position 2 >>>> I0430 06:08:49.509892 30349 leveldb.cpp:341] Persisting action (16 >>>> bytes) to leveldb took 67784ns >>>> I0430 06:08:49.509946 30349 replica.cpp:664] Persisted action at 2 >>>> I0430 06:08:49.510172 30349 replica.cpp:643] Replica received learned >>>> notice for position 2 >>>> I0430 06:08:49.510367 30349 leveldb.cpp:341] Persisting action (18 >>>> bytes) to leveldb took 94531ns >>>> I0430 06:08:49.510431 30349 leveldb.cpp:399] Deleting ~1 keys from >>>> leveldb took 9623ns >>>> I0430 06:08:49.510480 30349 replica.cpp:664] Persisted action at 2 >>>> I0430 06:08:49.510532 30349 replica.cpp:649] Replica learned TRUNCATE >>>> action at position 2 >>>> I0430 06:08:50.506840 30342 hierarchical_allocator_process.hpp:726] No >>>> resources available to allocate! >>>> I0430 06:08:50.506911 30342 hierarchical_allocator_process.hpp:688] >>>> Performed allocation for 0 slaves in 117128ns >>>> I0430 06:08:51.510942 30342 hierarchical_allocator_process.hpp:726] No >>>> resources available to allocate! >>>> I0430 06:08:51.510982 30342 hierarchical_allocator_process.hpp:688] >>>> Performed allocation for 0 slaves in 54612ns >>>> I0430 06:08:52.513665 30343 hierarchical_allocator_process.hpp:726] No >>>> resources available to allocate! >>>> I0430 06:08:52.513713 30343 hierarchical_allocator_process.hpp:688] >>>> Performed allocation for 0 slaves in 90420ns >>>> I0430 06:08:53.514034 30343 hierarchical_allocator_process.hpp:726] No >>>> resources available to allocate! >>>> I0430 06:08:53.514070 30343 hierarchical_allocator_process.hpp:688] >>>> Performed allocation for 0 slaves in 48216ns >>>> I0430 06:08:54.504179 30348 master.cpp:104] No whitelist given. >>>> Advertising offers for all slaves >>>> I0430 06:08:54.514416 30348 hierarchical_allocator_process.hpp:726] No >>>> resources available to allocate! >>>> I0430 06:08:54.514502 30348 hierarchical_allocator_process.hpp:688] >>>> Performed allocation for 0 slaves in 110788ns >>>> I0430 06:08:55.518991 30343 hierarchical_allocator_process.hpp:726] No >>>> resources available to allocate! >>>> I0430 06:08:55.519031 30343 hierarchical_allocator_process.hpp:688] >>>> Performed allocation for 0 slaves in 53319ns >>>> I0430 06:08:56.519583 30343 hierarchical_allocator_process.hpp:726] No >>>> resources available to allocate! >>>> I0430 06:08:56.519654 30343 hierarchical_allocator_process.hpp:688] >>>> Performed allocation for 0 slaves in 85551ns >>>> I0430 06:08:57.522794 30343 hierarchical_allocator_process.hpp:726] No >>>> resources available to allocate! >>>> I0430 06:08:57.522855 30343 hierarchical_allocator_process.hpp:688] >>>> Performed allocation for 0 slaves in 78093ns >>>> I0430 06:08:58.526785 30343 hierarchical_allocator_process.hpp:726] No >>>> resources available to allocate! >>>> I0430 06:08:58.526844 30343 hierarchical_allocator_process.hpp:688] >>>> Performed allocation for 0 slaves in 73657ns >>>> I0430 06:08:59.504978 30343 master.cpp:104] No whitelist given. >>>> Advertising offers for all slaves >>>> F0430 06:08:59.511245 30322 cluster.hpp:379] Failed to wait for _recover >>>> *** Check failure stack trace: *** >>>> I0430 06:08:59.527694 30343 hierarchical_allocator_process.hpp:726] No >>>> resources available to allocate! >>>> I0430 06:08:59.562788 30343 hierarchical_allocator_process.hpp:688] >>>> Performed allocation for 0 slaves in 35.083369ms >>>> @ 0x2ac97f1a0dbd google::LogMessage::Fail() >>>> @ 0x2ac97f1a2e4f google::LogMessage::SendToLog() >>>> @ 0x2ac97f1a09ac google::LogMessage::Flush() >>>> @ 0x2ac97f1a36bd google::LogMessageFatal::~LogMessageFatal() >>>> @ 0x716769 >>>> mesos::internal::tests::Cluster::Masters::start() >>>> @ 0x710da3 >>>> mesos::internal::tests::MesosTest::StartMaster() >>>> @ 0x571386 >>>> AuthenticationTest_RetrySlaveAuthentication_Test::TestBody() >>>> @ 0x86706d >>>> testing::internal::HandleExceptionsInMethodIfSupported<>() >>>> @ 0x85f6a1 testing::Test::Run() >>>> @ 0x85f786 testing::TestInfo::Run() >>>> @ 0x85f8c7 testing::TestCase::Run() >>>> @ 0x85fc2e testing::internal::UnitTestImpl::RunAllTests() >>>> @ 0x866bed >>>> testing::internal::HandleExceptionsInMethodIfSupported<>() >>>> @ 0x85ecfe testing::UnitTest::Run() >>>> @ 0x49f900 main >>>> @ 0x2ac9805e076d (unknown) >>>> @ 0x4a91d1 (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 >>>> Build step 'Execute shell' marked build as failure >>>> >>> >>> >> >
