You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@mesos.apache.org by Apache Jenkins Server <je...@builds.apache.org> on 2014/04/30 08:09:00 UTC
Build failed in Jenkins:
Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui
#2101
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 : master@67.195.138.8: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 master@67.195.138.8: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 master@67.195.138.8:58511
I0430 06:08:49.459740 30348 sched.cpp:268] Authenticating with master master@67.195.138.8: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 master@67.195.138.8:58511
I0430 06:08:49.463973 30348 sched.cpp:323] Failed to authenticate with master master@67.195.138.8:58511: master changed
I0430 06:08:49.463994 30348 sched.cpp:268] Authenticating with master master@67.195.138.8: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 master@67.195.138.8:58511
I0430 06:08:49.464581 30348 sched.cpp:461] Sending registration request to master@67.195.138.8: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 : master@67.195.138.8: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 master@67.195.138.8: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
Jenkins build is back to normal :
Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui
#2106
Posted by Apache Jenkins Server <je...@builds.apache.org>.
See <https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/2106/changes>
Build failed in Jenkins:
Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui
#2105
Posted by Apache Jenkins Server <je...@builds.apache.org>.
See <https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/2105/changes>
Changes:
[yujie.jay] Updated the 'contains' method in stout IntervalSet to support more
[yujie.jay] Added stream functions for stout Interval and IntervalSet.
[benjamin.hindman] Introduced base64::encode/decode in stout.
[benjamin.hindman] Decode percent-encoded paths.
[yujie.jay] Fixed gcc-4.8 compilation error for stout interval set.
------------------------------------------
[...truncated 14504 lines...]
I0501 07:50:54.086503 7053 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:50:54.086530 7053 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 37192ns
I0501 07:50:55.087604 7056 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:50:55.087630 7056 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 36044ns
I0501 07:50:55.259860 7054 master.cpp:104] No whitelist given. Advertising offers for all slaves
I0501 07:50:56.087734 7055 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:50:56.087765 7055 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 39683ns
I0501 07:50:57.087837 7052 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:50:57.087864 7052 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 37216ns
I0501 07:50:58.087944 7053 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:50:58.087980 7053 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 44344ns
I0501 07:50:59.088053 7049 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:50:59.088083 7049 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 41614ns
I0501 07:51:00.088145 7056 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:00.088158 7056 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 17954ns
I0501 07:51:00.260411 7054 master.cpp:104] No whitelist given. Advertising offers for all slaves
I0501 07:51:01.088343 7052 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:01.088376 7052 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 35612ns
I0501 07:51:02.089457 7051 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:02.089480 7051 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 26384ns
I0501 07:51:03.090564 7051 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:03.090587 7051 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 27014ns
I0501 07:51:04.091684 7051 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:04.091711 7051 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 31694ns
I0501 07:51:05.092808 7051 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:05.092836 7051 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 35135ns
I0501 07:51:05.261049 7051 master.cpp:104] No whitelist given. Advertising offers for all slaves
I0501 07:51:06.093047 7055 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:06.093075 7055 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 38018ns
I0501 07:51:07.094125 7055 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:07.094146 7055 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 24110ns
I0501 07:51:08.095252 7049 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:08.095264 7049 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 18326ns
I0501 07:51:09.096364 7054 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:09.096376 7054 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 27959ns
I0501 07:51:10.097455 7056 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:10.097466 7056 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 16190ns
I0501 07:51:10.261701 7054 master.cpp:104] No whitelist given. Advertising offers for all slaves
I0501 07:51:11.097579 7050 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:11.097591 7050 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 14402ns
I0501 07:51:12.098675 7056 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:12.098686 7056 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 13301ns
I0501 07:51:13.099792 7049 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:13.099809 7049 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 27023ns
I0501 07:51:14.100918 7056 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:14.100944 7056 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 36005ns
I0501 07:51:15.101989 7053 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:15.102037 7053 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 62913ns
I0501 07:51:15.262210 7054 master.cpp:104] No whitelist given. Advertising offers for all slaves
I0501 07:51:16.103134 7051 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:16.103154 7051 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 27185ns
I0501 07:51:17.104224 7052 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:17.104234 7052 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 14019ns
I0501 07:51:18.104351 7055 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:18.104387 7055 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 53734ns
I0501 07:51:19.104470 7051 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:19.104496 7051 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 31984ns
I0501 07:51:20.105608 7052 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:20.105631 7052 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 27464ns
I0501 07:51:20.262850 7056 master.cpp:104] No whitelist given. Advertising offers for all slaves
I0501 07:51:21.105733 7050 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:21.105751 7050 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 23873ns
I0501 07:51:22.105834 7054 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:22.105845 7054 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 17073ns
I0501 07:51:23.106937 7053 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:23.106950 7053 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 14747ns
I0501 07:51:24.108031 7051 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:24.108052 7051 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 24077ns
I0501 07:51:25.109109 7051 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:25.109122 7051 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 12687ns
I0501 07:51:25.263341 7051 master.cpp:104] No whitelist given. Advertising offers for all slaves
I0501 07:51:26.109591 7055 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:26.109616 7055 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 26978ns
I0501 07:51:27.110720 7052 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:27.110750 7052 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 40343ns
I0501 07:51:28.111801 7055 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:28.111817 7055 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 20585ns
I0501 07:51:29.112887 7050 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:29.112898 7050 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 15077ns
I0501 07:51:30.113966 7050 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:30.113976 7050 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 11637ns
I0501 07:51:30.264196 7050 master.cpp:104] No whitelist given. Advertising offers for all slaves
I0501 07:51:31.114138 7053 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:31.114171 7053 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 46970ns
I0501 07:51:32.115197 7050 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:32.115233 7050 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 46444ns
I0501 07:51:33.116220 7055 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:33.116255 7055 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 41497ns
I0501 07:51:34.116334 7055 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:34.116420 7055 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 93027ns
I0501 07:51:35.117578 7052 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:35.117614 7052 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 50344ns
I0501 07:51:35.264791 7054 master.cpp:104] No whitelist given. Advertising offers for all slaves
I0501 07:51:36.118607 7051 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:36.118626 7051 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 27363ns
I0501 07:51:37.119720 7056 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:37.119756 7056 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 45404ns
I0501 07:51:38.120805 7055 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:38.120832 7055 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 44972ns
I0501 07:51:39.121850 7052 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:39.121878 7052 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 38120ns
I0501 07:51:40.122890 7051 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:40.122927 7051 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 51400ns
I0501 07:51:40.265090 7050 master.cpp:104] No whitelist given. Advertising offers for all slaves
I0501 07:51:41.123888 7049 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:41.123908 7049 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 22970ns
I0501 07:51:42.125061 7056 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:42.125094 7056 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 48304ns
I0501 07:51:43.126133 7055 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:43.126163 7055 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 35072ns
I0501 07:51:44.127219 7055 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:44.127250 7055 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 35321ns
I0501 07:51:45.128301 7055 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:45.128324 7055 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 24959ns
I0501 07:51:45.265511 7055 master.cpp:104] No whitelist given. Advertising offers for all slaves
I0501 07:51:46.128407 7055 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:46.128422 7055 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 21848ns
I0501 07:51:47.128489 7052 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:47.128506 7052 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 19745ns
I0501 07:51:48.128576 7055 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:48.128600 7055 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 26891ns
I0501 07:51:49.128659 7052 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:49.128674 7052 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 16835ns
I0501 07:51:50.128794 7050 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:50.128841 7050 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 56725ns
I0501 07:51:50.266003 7054 master.cpp:104] No whitelist given. Advertising offers for all slaves
I0501 07:51:51.128907 7051 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:51.128926 7051 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 23237ns
I0501 07:51:52.129009 7056 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:52.129060 7056 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 59169ns
I0501 07:51:53.130185 7054 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:53.130220 7054 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 44545ns
I0501 07:51:54.131232 7052 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:54.131250 7052 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 22343ns
I0501 07:51:55.132310 7052 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:55.132320 7052 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 11367ns
I0501 07:51:55.266518 7052 master.cpp:104] No whitelist given. Advertising offers for all slaves
I0501 07:51:56.132424 7052 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:56.132437 7052 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 18380ns
I0501 07:51:57.132529 7055 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:57.132556 7055 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 40736ns
I0501 07:51:58.132645 7052 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:58.132670 7052 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 37286ns
I0501 07:51:59.133801 7050 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:51:59.133831 7050 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 42320ns
I0501 07:52:00.134943 7055 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:52:00.134969 7055 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 32822ns
I0501 07:52:00.267150 7053 master.cpp:104] No whitelist given. Advertising offers for all slaves
I0501 07:52:01.135067 7050 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:52:01.135100 7050 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 46843ns
I0501 07:52:02.136204 7049 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:52:02.136236 7049 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 38746ns
I0501 07:52:03.137306 7052 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:52:03.137327 7052 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 30503ns
I0501 07:52:04.138396 7055 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:52:04.138413 7055 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 22379ns
I0501 07:52:05.138490 7053 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:52:05.138506 7053 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 23888ns
I0501 07:52:05.267724 7050 master.cpp:104] No whitelist given. Advertising offers for all slaves
I0501 07:52:06.138651 7052 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:52:06.138682 7052 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 41263ns
I0501 07:52:07.139765 7049 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:52:07.139796 7049 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 42116ns
I0501 07:52:08.140910 7055 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:52:08.140949 7055 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 46670ns
I0501 07:52:09.141991 7053 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:52:09.142019 7053 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 34279ns
I0501 07:52:10.143141 7050 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:52:10.143169 7050 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 37811ns
I0501 07:52:10.268316 7054 master.cpp:104] No whitelist given. Advertising offers for all slaves
I0501 07:52:11.144286 7049 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:52:11.144306 7049 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 26804ns
I0501 07:52:12.145400 7055 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:52:12.145423 7055 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 30413ns
I0501 07:52:13.146461 7055 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:52:13.146474 7055 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 15791ns
I0501 07:52:14.147550 7055 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:52:14.147560 7055 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 11459ns
I0501 07:52:15.148639 7055 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:52:15.148648 7055 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 11235ns
I0501 07:52:15.268833 7055 master.cpp:104] No whitelist given. Advertising offers for all slaves
I0501 07:52:16.148742 7055 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:52:16.148752 7055 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 12069ns
I0501 07:52:17.148825 7052 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:52:17.148859 7052 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 43417ns
I0501 07:52:18.148923 7054 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:52:18.148937 7054 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 18788ns
I0501 07:52:19.150028 7056 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:52:19.150043 7056 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 18992ns
I0501 07:52:20.151128 7054 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:52:20.151139 7054 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 16289ns
I0501 07:52:20.269335 7050 master.cpp:104] No whitelist given. Advertising offers for all slaves
I0501 07:52:21.151372 7051 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:52:21.151399 7051 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 34315ns
I0501 07:52:22.152468 7052 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:52:22.152483 7052 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 18908ns
I0501 07:52:23.152647 7056 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:52:23.152679 7056 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 43151ns
I0501 07:52:24.153715 7052 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:52:24.153750 7052 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 50784ns
I0501 07:52:25.153856 7053 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:52:25.153898 7053 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 61099ns
I0501 07:52:25.270016 7054 master.cpp:104] No whitelist given. Advertising offers for all slaves
I0501 07:52:26.155043 7055 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:52:26.155077 7055 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 48034ns
I0501 07:52:27.156110 7049 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:52:27.156136 7049 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 37234ns
I0501 07:52:28.157232 7050 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:52:28.157261 7050 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 42727ns
I0501 07:52:29.158327 7054 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:52:29.158349 7054 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 26483ns
I0501 07:52:30.159433 7053 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:52:30.159453 7053 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 29231ns
I0501 07:52:30.270630 7055 master.cpp:104] No whitelist given. Advertising offers for all slaves
I0501 07:52:31.159553 7051 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:52:31.159572 7051 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 27329ns
I0501 07:52:32.159687 7054 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:52:32.159713 7054 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 36865ns
I0501 07:52:33.159828 7056 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:52:33.159857 7056 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 36614ns
I0501 07:52:34.159963 7053 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:52:34.159986 7053 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 32822ns
I0501 07:52:35.160076 7055 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:52:35.160105 7055 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 37076ns
I0501 07:52:35.271224 7055 master.cpp:104] No whitelist given. Advertising offers for all slaves
I0501 07:52:36.160152 7055 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:52:36.160171 7055 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 21626ns
I0501 07:52:37.160255 7051 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:52:37.160271 7051 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 25370ns
I0501 07:52:38.160341 7056 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:52:38.160390 7056 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 54175ns
I0501 07:52:39.161527 7050 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:52:39.161556 7050 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 36995ns
I0501 07:52:40.162623 7054 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:52:40.162653 7054 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 39445ns
I0501 07:52:40.271754 7055 master.cpp:104] No whitelist given. Advertising offers for all slaves
I0501 07:52:41.162772 7049 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:52:41.162807 7049 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 41906ns
I0501 07:52:42.163965 7056 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:52:42.164010 7056 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 59341ns
I0501 07:52:43.165086 7053 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:52:43.165113 7053 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 37765ns
I0501 07:52:44.166177 7054 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:52:44.166206 7054 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 40312ns
I0501 07:52:45.167296 7049 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0501 07:52:45.167327 7049 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 43286ns
I0501 07:52:45.272517 7050 master.cpp:104] No whitelist given. Advertising offers for all slaves
Build timed out (after 120 minutes). Marking the build as failed.
Build was aborted
Re: Build failed in Jenkins: Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui
#2103
Posted by Vinod Kone <vi...@gmail.com>.
https://issues.apache.org/jira/browse/MESOS-1273
On Wed, Apr 30, 2014 at 4:06 PM, Apache Jenkins Server <
jenkins@builds.apache.org> wrote:
> See <
> https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/2103/changes
> >
>
> Changes:
>
> [bmahler] Allowed timing of Future completions in Timer.
>
> [bmahler] Improved timing accuracy in the Registrar.
>
> [dlester] Adds Netflix to #PoweredByMesos list.
>
> ------------------------------------------
> [...truncated 26713 lines...]
> I0430 23:04:49.886162 18172 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 45536ns
> I0430 23:04:50.887214 18170 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:04:50.887229 18170 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 20981ns
> I0430 23:04:51.888315 18171 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:04:51.888345 18171 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 37345ns
> I0430 23:04:52.889410 18167 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:04:52.889426 18167 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 22677ns
> I0430 23:04:53.694392 18170 master.cpp:104] No whitelist given.
> Advertising offers for all slaves
> I0430 23:04:53.889608 18166 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:04:53.889638 18166 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 40879ns
> I0430 23:04:54.890691 18168 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:04:54.890727 18168 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 46399ns
> I0430 23:04:55.891832 18168 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:04:55.891870 18168 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 46592ns
> I0430 23:04:56.892966 18168 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:04:56.892997 18168 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 41359ns
> I0430 23:04:57.894106 18168 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:04:57.894137 18168 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 41626ns
> I0430 23:04:58.695003 18168 master.cpp:104] No whitelist given.
> Advertising offers for all slaves
> I0430 23:04:58.894254 18168 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:04:58.894285 18168 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 38779ns
> I0430 23:04:59.895360 18168 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:04:59.895393 18168 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 43135ns
> I0430 23:05:00.896440 18168 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:00.896472 18168 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 40642ns
> I0430 23:05:01.897531 18168 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:01.897563 18168 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 41852ns
> I0430 23:05:02.898618 18168 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:02.898650 18168 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 41626ns
> I0430 23:05:03.695530 18168 master.cpp:104] No whitelist given.
> Advertising offers for all slaves
> I0430 23:05:03.898790 18168 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:03.898830 18168 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 54466ns
> I0430 23:05:04.899857 18170 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:04.899898 18170 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 46195ns
> I0430 23:05:05.901027 18165 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:05.901062 18165 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 45526ns
> I0430 23:05:06.901269 18167 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:06.901284 18167 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 21395ns
> I0430 23:05:07.901434 18169 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:07.901465 18169 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 45695ns
> I0430 23:05:08.696318 18170 master.cpp:104] No whitelist given.
> Advertising offers for all slaves
> I0430 23:05:08.901641 18168 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:08.901671 18168 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 45380ns
> I0430 23:05:09.902678 18166 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:09.902716 18166 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 47374ns
> I0430 23:05:10.903798 18170 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:10.903815 18170 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 19931ns
> I0430 23:05:11.903893 18167 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:11.903924 18167 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 40999ns
> I0430 23:05:12.905011 18168 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:12.905027 18168 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 20588ns
> I0430 23:05:13.696938 18171 master.cpp:104] No whitelist given.
> Advertising offers for all slaves
> I0430 23:05:13.905159 18172 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:13.905192 18172 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 42938ns
> I0430 23:05:14.906244 18166 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:14.906257 18166 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 17120ns
> I0430 23:05:15.907333 18165 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:15.907347 18165 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 18431ns
> I0430 23:05:16.908437 18169 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:16.908452 18169 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 20108ns
> I0430 23:05:17.909538 18170 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:17.909553 18170 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 20459ns
> I0430 23:05:18.697468 18166 master.cpp:104] No whitelist given.
> Advertising offers for all slaves
> I0430 23:05:18.909718 18165 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:18.909746 18165 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 36922ns
> I0430 23:05:19.910792 18167 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:19.910819 18167 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 33218ns
> I0430 23:05:20.911936 18168 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:20.911969 18168 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 45187ns
> I0430 23:05:21.913053 18166 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:21.913069 18166 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 17792ns
> I0430 23:05:22.913163 18171 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:22.913198 18171 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 46963ns
> I0430 23:05:23.698127 18165 master.cpp:104] No whitelist given.
> Advertising offers for all slaves
> I0430 23:05:23.913422 18167 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:23.913457 18167 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 44698ns
> I0430 23:05:24.914561 18172 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:24.914584 18172 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 34232ns
> I0430 23:05:25.914685 18171 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:25.914705 18171 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 26299ns
> I0430 23:05:26.915262 18166 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:26.915278 18166 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 20969ns
> I0430 23:05:27.916410 18169 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:27.916426 18169 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 24587ns
> I0430 23:05:28.698359 18168 master.cpp:104] No whitelist given.
> Advertising offers for all slaves
> I0430 23:05:28.916625 18167 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:28.916638 18167 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 20192ns
> I0430 23:05:29.916726 18172 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:29.916739 18172 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 15597ns
> I0430 23:05:30.916877 18171 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:30.916915 18171 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 54850ns
> I0430 23:05:31.917994 18165 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:31.918020 18165 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 35515ns
> I0430 23:05:32.919111 18170 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:32.919131 18170 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 24711ns
> I0430 23:05:33.699061 18172 master.cpp:104] No whitelist given.
> Advertising offers for all slaves
> I0430 23:05:33.919306 18168 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:33.919320 18168 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 22031ns
> I0430 23:05:34.920466 18169 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:34.920500 18169 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 46553ns
> I0430 23:05:35.921551 18171 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:35.921579 18171 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 37652ns
> I0430 23:05:36.922643 18165 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:36.922683 18165 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 47002ns
> I0430 23:05:37.923751 18165 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:37.923789 18165 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 47530ns
> I0430 23:05:38.699625 18165 master.cpp:104] No whitelist given.
> Advertising offers for all slaves
> I0430 23:05:38.924908 18165 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:38.924947 18165 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 49468ns
> I0430 23:05:39.926015 18165 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:39.926058 18165 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 53977ns
> I0430 23:05:40.927100 18165 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:40.927137 18165 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 48046ns
> I0430 23:05:41.928269 18165 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:41.928310 18165 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 51403ns
> I0430 23:05:42.929425 18165 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:42.929462 18165 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 46762ns
> I0430 23:05:43.700251 18165 master.cpp:104] No whitelist given.
> Advertising offers for all slaves
> I0430 23:05:43.929632 18165 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:43.929668 18165 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 44983ns
> I0430 23:05:44.930758 18165 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:44.930796 18165 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 49588ns
> I0430 23:05:45.931864 18165 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:45.931900 18165 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 45670ns
> I0430 23:05:46.932945 18165 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:46.932976 18165 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 39736ns
> I0430 23:05:47.934028 18165 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:47.934059 18165 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 40850ns
> I0430 23:05:48.700773 18165 master.cpp:104] No whitelist given.
> Advertising offers for all slaves
> I0430 23:05:48.935132 18165 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:48.935164 18165 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 41894ns
> I0430 23:05:49.936183 18165 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:49.936218 18165 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 44288ns
> I0430 23:05:50.937264 18165 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:50.937297 18165 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 42541ns
> I0430 23:05:51.938403 18165 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:51.938433 18165 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 39845ns
> I0430 23:05:52.939553 18165 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:52.939584 18165 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 40936ns
> I0430 23:05:53.701314 18165 master.cpp:104] No whitelist given.
> Advertising offers for all slaves
> I0430 23:05:53.939692 18165 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:53.939724 18165 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 41383ns
> I0430 23:05:54.940837 18165 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:54.940876 18165 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 49021ns
> I0430 23:05:55.941913 18167 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:55.941967 18167 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 67569ns
> I0430 23:05:56.943034 18168 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:56.943052 18168 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 21452ns
> I0430 23:05:57.944120 18169 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:57.944138 18169 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 22970ns
> I0430 23:05:58.701947 18166 master.cpp:104] No whitelist given.
> Advertising offers for all slaves
> I0430 23:05:58.944260 18171 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:58.944275 18171 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 20969ns
> I0430 23:05:59.944370 18168 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:05:59.944383 18168 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 31956ns
> I0430 23:06:00.945479 18169 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:06:00.945503 18169 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 26981ns
> I0430 23:06:01.946611 18172 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:06:01.946625 18172 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 18837ns
> I0430 23:06:02.947070 18167 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:06:02.947085 18167 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 17399ns
> I0430 23:06:03.703140 18166 master.cpp:104] No whitelist given.
> Advertising offers for all slaves
> I0430 23:06:03.947484 18171 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:06:03.947502 18171 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 20561ns
> I0430 23:06:04.948581 18165 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:06:04.948596 18165 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 22349ns
> I0430 23:06:05.949671 18172 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:06:05.949687 18172 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 17601ns
> I0430 23:06:06.950842 18166 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:06:06.950882 18166 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 49813ns
> I0430 23:06:07.951858 18171 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:06:07.951872 18171 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 16617ns
> I0430 23:06:08.703641 18165 master.cpp:104] No whitelist given.
> Advertising offers for all slaves
> I0430 23:06:08.952023 18169 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:06:08.952036 18169 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 16005ns
> I0430 23:06:09.953119 18172 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:06:09.953133 18172 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 16106ns
> I0430 23:06:10.954252 18166 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:06:10.954289 18166 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 48796ns
> I0430 23:06:11.955292 18165 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:06:11.955308 18165 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 17070ns
> I0430 23:06:12.956348 18170 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:06:12.956387 18170 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 41867ns
> I0430 23:06:13.704112 18172 master.cpp:104] No whitelist given.
> Advertising offers for all slaves
> I0430 23:06:13.956501 18171 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:06:13.956516 18171 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 17829ns
> I0430 23:06:14.957593 18167 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:06:14.957610 18167 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 18425ns
> I0430 23:06:15.958706 18166 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:06:15.958724 18166 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 23390ns
> I0430 23:06:16.959836 18168 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:06:16.959872 18168 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 43049ns
> I0430 23:06:17.960978 18168 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:06:17.961009 18168 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 43198ns
> I0430 23:06:18.704730 18172 master.cpp:104] No whitelist given.
> Advertising offers for all slaves
> I0430 23:06:18.961159 18165 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:06:18.961174 18165 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 23915ns
> I0430 23:06:19.962255 18171 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:06:19.962268 18171 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 20666ns
> I0430 23:06:20.963376 18169 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:06:20.963393 18169 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 19307ns
> I0430 23:06:21.963501 18166 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:06:21.963517 18166 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 18591ns
> I0430 23:06:22.964632 18168 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:06:22.964648 18168 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 18350ns
> I0430 23:06:23.705399 18170 master.cpp:104] No whitelist given.
> Advertising offers for all slaves
> I0430 23:06:23.964882 18170 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:06:23.964895 18170 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 14339ns
> I0430 23:06:24.965026 18167 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:06:24.965065 18167 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 49132ns
> I0430 23:06:25.966157 18170 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:06:25.966171 18170 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 17004ns
> I0430 23:06:26.966248 18172 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:06:26.966264 18172 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 18249ns
> I0430 23:06:27.966351 18171 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:06:27.966364 18171 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 16904ns
> I0430 23:06:28.706118 18165 master.cpp:104] No whitelist given.
> Advertising offers for all slaves
> I0430 23:06:28.966606 18171 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:06:28.966617 18171 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 13290ns
> I0430 23:06:29.966727 18165 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:06:29.966742 18165 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 14190ns
> I0430 23:06:30.966809 18166 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:06:30.966824 18166 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 18551ns
> I0430 23:06:31.966976 18171 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:06:31.966994 18171 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 18818ns
> I0430 23:06:32.968092 18165 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:06:32.968109 18165 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 20942ns
> I0430 23:06:33.706851 18172 master.cpp:104] No whitelist given.
> Advertising offers for all slaves
> I0430 23:06:33.968291 18169 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:06:33.968307 18169 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 18302ns
> I0430 23:06:34.968422 18166 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:06:34.968436 18166 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 16475ns
> I0430 23:06:35.969507 18170 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:06:35.969526 18170 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 20429ns
> I0430 23:06:36.969598 18167 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:06:36.969609 18167 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 15779ns
> I0430 23:06:37.969737 18168 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:06:37.969753 18168 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 19670ns
> I0430 23:06:38.707500 18167 master.cpp:104] No whitelist given.
> Advertising offers for all slaves
> I0430 23:06:38.969887 18172 hierarchical_allocator_process.hpp:726] No
> resources available to allocate!
> I0430 23:06:38.969903 18172 hierarchical_allocator_process.hpp:688]
> Performed allocation for 0 slaves in 20348ns
> Build timed out (after 120 minutes). Marking the build as failed.
> make[3]: *** [check-local] Terminated
> 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 failed in Jenkins:
Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui
#2103
Posted by Apache Jenkins Server <je...@builds.apache.org>.
See <https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/2103/changes>
Changes:
[bmahler] Allowed timing of Future completions in Timer.
[bmahler] Improved timing accuracy in the Registrar.
[dlester] Adds Netflix to #PoweredByMesos list.
------------------------------------------
[...truncated 26713 lines...]
I0430 23:04:49.886162 18172 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 45536ns
I0430 23:04:50.887214 18170 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:04:50.887229 18170 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 20981ns
I0430 23:04:51.888315 18171 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:04:51.888345 18171 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 37345ns
I0430 23:04:52.889410 18167 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:04:52.889426 18167 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 22677ns
I0430 23:04:53.694392 18170 master.cpp:104] No whitelist given. Advertising offers for all slaves
I0430 23:04:53.889608 18166 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:04:53.889638 18166 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 40879ns
I0430 23:04:54.890691 18168 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:04:54.890727 18168 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 46399ns
I0430 23:04:55.891832 18168 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:04:55.891870 18168 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 46592ns
I0430 23:04:56.892966 18168 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:04:56.892997 18168 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 41359ns
I0430 23:04:57.894106 18168 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:04:57.894137 18168 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 41626ns
I0430 23:04:58.695003 18168 master.cpp:104] No whitelist given. Advertising offers for all slaves
I0430 23:04:58.894254 18168 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:04:58.894285 18168 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 38779ns
I0430 23:04:59.895360 18168 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:04:59.895393 18168 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 43135ns
I0430 23:05:00.896440 18168 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:00.896472 18168 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 40642ns
I0430 23:05:01.897531 18168 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:01.897563 18168 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 41852ns
I0430 23:05:02.898618 18168 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:02.898650 18168 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 41626ns
I0430 23:05:03.695530 18168 master.cpp:104] No whitelist given. Advertising offers for all slaves
I0430 23:05:03.898790 18168 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:03.898830 18168 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 54466ns
I0430 23:05:04.899857 18170 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:04.899898 18170 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 46195ns
I0430 23:05:05.901027 18165 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:05.901062 18165 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 45526ns
I0430 23:05:06.901269 18167 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:06.901284 18167 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 21395ns
I0430 23:05:07.901434 18169 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:07.901465 18169 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 45695ns
I0430 23:05:08.696318 18170 master.cpp:104] No whitelist given. Advertising offers for all slaves
I0430 23:05:08.901641 18168 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:08.901671 18168 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 45380ns
I0430 23:05:09.902678 18166 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:09.902716 18166 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 47374ns
I0430 23:05:10.903798 18170 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:10.903815 18170 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 19931ns
I0430 23:05:11.903893 18167 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:11.903924 18167 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 40999ns
I0430 23:05:12.905011 18168 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:12.905027 18168 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 20588ns
I0430 23:05:13.696938 18171 master.cpp:104] No whitelist given. Advertising offers for all slaves
I0430 23:05:13.905159 18172 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:13.905192 18172 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 42938ns
I0430 23:05:14.906244 18166 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:14.906257 18166 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 17120ns
I0430 23:05:15.907333 18165 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:15.907347 18165 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 18431ns
I0430 23:05:16.908437 18169 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:16.908452 18169 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 20108ns
I0430 23:05:17.909538 18170 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:17.909553 18170 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 20459ns
I0430 23:05:18.697468 18166 master.cpp:104] No whitelist given. Advertising offers for all slaves
I0430 23:05:18.909718 18165 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:18.909746 18165 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 36922ns
I0430 23:05:19.910792 18167 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:19.910819 18167 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 33218ns
I0430 23:05:20.911936 18168 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:20.911969 18168 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 45187ns
I0430 23:05:21.913053 18166 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:21.913069 18166 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 17792ns
I0430 23:05:22.913163 18171 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:22.913198 18171 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 46963ns
I0430 23:05:23.698127 18165 master.cpp:104] No whitelist given. Advertising offers for all slaves
I0430 23:05:23.913422 18167 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:23.913457 18167 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 44698ns
I0430 23:05:24.914561 18172 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:24.914584 18172 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 34232ns
I0430 23:05:25.914685 18171 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:25.914705 18171 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 26299ns
I0430 23:05:26.915262 18166 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:26.915278 18166 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 20969ns
I0430 23:05:27.916410 18169 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:27.916426 18169 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 24587ns
I0430 23:05:28.698359 18168 master.cpp:104] No whitelist given. Advertising offers for all slaves
I0430 23:05:28.916625 18167 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:28.916638 18167 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 20192ns
I0430 23:05:29.916726 18172 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:29.916739 18172 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 15597ns
I0430 23:05:30.916877 18171 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:30.916915 18171 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 54850ns
I0430 23:05:31.917994 18165 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:31.918020 18165 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 35515ns
I0430 23:05:32.919111 18170 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:32.919131 18170 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 24711ns
I0430 23:05:33.699061 18172 master.cpp:104] No whitelist given. Advertising offers for all slaves
I0430 23:05:33.919306 18168 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:33.919320 18168 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 22031ns
I0430 23:05:34.920466 18169 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:34.920500 18169 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 46553ns
I0430 23:05:35.921551 18171 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:35.921579 18171 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 37652ns
I0430 23:05:36.922643 18165 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:36.922683 18165 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 47002ns
I0430 23:05:37.923751 18165 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:37.923789 18165 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 47530ns
I0430 23:05:38.699625 18165 master.cpp:104] No whitelist given. Advertising offers for all slaves
I0430 23:05:38.924908 18165 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:38.924947 18165 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 49468ns
I0430 23:05:39.926015 18165 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:39.926058 18165 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 53977ns
I0430 23:05:40.927100 18165 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:40.927137 18165 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 48046ns
I0430 23:05:41.928269 18165 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:41.928310 18165 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 51403ns
I0430 23:05:42.929425 18165 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:42.929462 18165 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 46762ns
I0430 23:05:43.700251 18165 master.cpp:104] No whitelist given. Advertising offers for all slaves
I0430 23:05:43.929632 18165 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:43.929668 18165 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 44983ns
I0430 23:05:44.930758 18165 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:44.930796 18165 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 49588ns
I0430 23:05:45.931864 18165 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:45.931900 18165 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 45670ns
I0430 23:05:46.932945 18165 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:46.932976 18165 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 39736ns
I0430 23:05:47.934028 18165 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:47.934059 18165 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 40850ns
I0430 23:05:48.700773 18165 master.cpp:104] No whitelist given. Advertising offers for all slaves
I0430 23:05:48.935132 18165 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:48.935164 18165 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 41894ns
I0430 23:05:49.936183 18165 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:49.936218 18165 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 44288ns
I0430 23:05:50.937264 18165 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:50.937297 18165 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 42541ns
I0430 23:05:51.938403 18165 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:51.938433 18165 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 39845ns
I0430 23:05:52.939553 18165 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:52.939584 18165 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 40936ns
I0430 23:05:53.701314 18165 master.cpp:104] No whitelist given. Advertising offers for all slaves
I0430 23:05:53.939692 18165 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:53.939724 18165 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 41383ns
I0430 23:05:54.940837 18165 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:54.940876 18165 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 49021ns
I0430 23:05:55.941913 18167 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:55.941967 18167 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 67569ns
I0430 23:05:56.943034 18168 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:56.943052 18168 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 21452ns
I0430 23:05:57.944120 18169 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:57.944138 18169 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 22970ns
I0430 23:05:58.701947 18166 master.cpp:104] No whitelist given. Advertising offers for all slaves
I0430 23:05:58.944260 18171 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:58.944275 18171 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 20969ns
I0430 23:05:59.944370 18168 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:05:59.944383 18168 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 31956ns
I0430 23:06:00.945479 18169 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:06:00.945503 18169 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 26981ns
I0430 23:06:01.946611 18172 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:06:01.946625 18172 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 18837ns
I0430 23:06:02.947070 18167 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:06:02.947085 18167 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 17399ns
I0430 23:06:03.703140 18166 master.cpp:104] No whitelist given. Advertising offers for all slaves
I0430 23:06:03.947484 18171 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:06:03.947502 18171 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 20561ns
I0430 23:06:04.948581 18165 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:06:04.948596 18165 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 22349ns
I0430 23:06:05.949671 18172 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:06:05.949687 18172 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 17601ns
I0430 23:06:06.950842 18166 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:06:06.950882 18166 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 49813ns
I0430 23:06:07.951858 18171 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:06:07.951872 18171 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 16617ns
I0430 23:06:08.703641 18165 master.cpp:104] No whitelist given. Advertising offers for all slaves
I0430 23:06:08.952023 18169 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:06:08.952036 18169 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 16005ns
I0430 23:06:09.953119 18172 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:06:09.953133 18172 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 16106ns
I0430 23:06:10.954252 18166 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:06:10.954289 18166 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 48796ns
I0430 23:06:11.955292 18165 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:06:11.955308 18165 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 17070ns
I0430 23:06:12.956348 18170 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:06:12.956387 18170 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 41867ns
I0430 23:06:13.704112 18172 master.cpp:104] No whitelist given. Advertising offers for all slaves
I0430 23:06:13.956501 18171 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:06:13.956516 18171 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 17829ns
I0430 23:06:14.957593 18167 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:06:14.957610 18167 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 18425ns
I0430 23:06:15.958706 18166 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:06:15.958724 18166 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 23390ns
I0430 23:06:16.959836 18168 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:06:16.959872 18168 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 43049ns
I0430 23:06:17.960978 18168 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:06:17.961009 18168 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 43198ns
I0430 23:06:18.704730 18172 master.cpp:104] No whitelist given. Advertising offers for all slaves
I0430 23:06:18.961159 18165 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:06:18.961174 18165 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 23915ns
I0430 23:06:19.962255 18171 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:06:19.962268 18171 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 20666ns
I0430 23:06:20.963376 18169 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:06:20.963393 18169 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 19307ns
I0430 23:06:21.963501 18166 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:06:21.963517 18166 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 18591ns
I0430 23:06:22.964632 18168 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:06:22.964648 18168 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 18350ns
I0430 23:06:23.705399 18170 master.cpp:104] No whitelist given. Advertising offers for all slaves
I0430 23:06:23.964882 18170 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:06:23.964895 18170 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 14339ns
I0430 23:06:24.965026 18167 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:06:24.965065 18167 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 49132ns
I0430 23:06:25.966157 18170 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:06:25.966171 18170 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 17004ns
I0430 23:06:26.966248 18172 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:06:26.966264 18172 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 18249ns
I0430 23:06:27.966351 18171 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:06:27.966364 18171 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 16904ns
I0430 23:06:28.706118 18165 master.cpp:104] No whitelist given. Advertising offers for all slaves
I0430 23:06:28.966606 18171 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:06:28.966617 18171 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 13290ns
I0430 23:06:29.966727 18165 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:06:29.966742 18165 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 14190ns
I0430 23:06:30.966809 18166 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:06:30.966824 18166 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 18551ns
I0430 23:06:31.966976 18171 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:06:31.966994 18171 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 18818ns
I0430 23:06:32.968092 18165 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:06:32.968109 18165 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 20942ns
I0430 23:06:33.706851 18172 master.cpp:104] No whitelist given. Advertising offers for all slaves
I0430 23:06:33.968291 18169 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:06:33.968307 18169 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 18302ns
I0430 23:06:34.968422 18166 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:06:34.968436 18166 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 16475ns
I0430 23:06:35.969507 18170 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:06:35.969526 18170 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 20429ns
I0430 23:06:36.969598 18167 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:06:36.969609 18167 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 15779ns
I0430 23:06:37.969737 18168 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:06:37.969753 18168 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 19670ns
I0430 23:06:38.707500 18167 master.cpp:104] No whitelist given. Advertising offers for all slaves
I0430 23:06:38.969887 18172 hierarchical_allocator_process.hpp:726] No resources available to allocate!
I0430 23:06:38.969903 18172 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 20348ns
Build timed out (after 120 minutes). Marking the build as failed.
make[3]: *** [check-local] Terminated
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 failed in Jenkins:
Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui
#2102
Posted by Apache Jenkins Server <je...@builds.apache.org>.
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 : master@140.211.11.27: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 master@140.211.11.27: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 master@140.211.11.27:51291
I0430 17:24:22.783206 10614 slave.cpp:585] Authenticating with master master@140.211.11.27:51291
I0430 17:24:22.783229 10618 status_update_manager.cpp:167] New master detected at master@140.211.11.27: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 master@140.211.11.27:51291
I0430 17:24:22.784858 10620 sched.cpp:268] Authenticating with master master@140.211.11.27: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 master@140.211.11.27: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 master@140.211.11.27:51291
I0430 17:24:22.786470 10620 sched.cpp:461] Sending registration request to master@140.211.11.27: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 master@140.211.11.27: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 master@140.211.11.27: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 master@140.211.11.27:51291
I0430 17:24:22.898501 10622 slave.cpp:585] Authenticating with master master@140.211.11.27: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 master@140.211.11.27: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 master@140.211.11.27: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 master@140.211.11.27: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 master@140.211.11.27: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
Re: Build failed in Jenkins: Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui
#2101
Posted by Benjamin Mahler <be...@gmail.com>.
Just pushed the fix.
On Wed, Apr 30, 2014 at 8:31 AM, Benjamin Mahler
<be...@gmail.com>wrote:
> Thanks for digging in Adam! I will get this fixed.
>
>
> On Wed, Apr 30, 2014 at 12:29 AM, Adam Bordelon <ad...@mesosphere.io>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 <vi...@gmail.com> wrote:
>>
>>> hey adam can you triage this?
>>>
>>>
>>> On Tue, Apr 29, 2014 at 11:09 PM, Apache Jenkins Server <
>>> jenkins@builds.apache.org> 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 :
>>>> master@67.195.138.8: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
>>>> master@67.195.138.8: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
>>>> master@67.195.138.8:58511
>>>> I0430 06:08:49.459740 30348 sched.cpp:268] Authenticating with master
>>>> master@67.195.138.8: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
>>>> master@67.195.138.8:58511
>>>> I0430 06:08:49.463973 30348 sched.cpp:323] Failed to authenticate with
>>>> master master@67.195.138.8:58511: master changed
>>>> I0430 06:08:49.463994 30348 sched.cpp:268] Authenticating with master
>>>> master@67.195.138.8: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 master@67.195.138.8:58511
>>>> I0430 06:08:49.464581 30348 sched.cpp:461] Sending registration request
>>>> to master@67.195.138.8: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 :
>>>> master@67.195.138.8: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
>>>> master@67.195.138.8: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
>>>>
>>>
>>>
>>
>
Re: Build failed in Jenkins: Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui
#2101
Posted by Benjamin Mahler <be...@gmail.com>.
Thanks for digging in Adam! I will get this fixed.
On Wed, Apr 30, 2014 at 12:29 AM, Adam Bordelon <ad...@mesosphere.io> 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 <vi...@gmail.com> wrote:
>
>> hey adam can you triage this?
>>
>>
>> On Tue, Apr 29, 2014 at 11:09 PM, Apache Jenkins Server <
>> jenkins@builds.apache.org> 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 :
>>> master@67.195.138.8: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
>>> master@67.195.138.8: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
>>> master@67.195.138.8:58511
>>> I0430 06:08:49.459740 30348 sched.cpp:268] Authenticating with master
>>> master@67.195.138.8: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
>>> master@67.195.138.8:58511
>>> I0430 06:08:49.463973 30348 sched.cpp:323] Failed to authenticate with
>>> master master@67.195.138.8:58511: master changed
>>> I0430 06:08:49.463994 30348 sched.cpp:268] Authenticating with master
>>> master@67.195.138.8: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 master@67.195.138.8:58511
>>> I0430 06:08:49.464581 30348 sched.cpp:461] Sending registration request
>>> to master@67.195.138.8: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 :
>>> master@67.195.138.8: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
>>> master@67.195.138.8: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
>>>
>>
>>
>
Re: Build failed in Jenkins: Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui
#2101
Posted by Adam Bordelon <ad...@mesosphere.io>.
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 <vi...@gmail.com> wrote:
> hey adam can you triage this?
>
>
> On Tue, Apr 29, 2014 at 11:09 PM, Apache Jenkins Server <
> jenkins@builds.apache.org> 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 :
>> master@67.195.138.8: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
>> master@67.195.138.8: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
>> master@67.195.138.8:58511
>> I0430 06:08:49.459740 30348 sched.cpp:268] Authenticating with master
>> master@67.195.138.8: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
>> master@67.195.138.8:58511
>> I0430 06:08:49.463973 30348 sched.cpp:323] Failed to authenticate with
>> master master@67.195.138.8:58511: master changed
>> I0430 06:08:49.463994 30348 sched.cpp:268] Authenticating with master
>> master@67.195.138.8: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 master@67.195.138.8:58511
>> I0430 06:08:49.464581 30348 sched.cpp:461] Sending registration request
>> to master@67.195.138.8: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 :
>> master@67.195.138.8: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
>> master@67.195.138.8: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
>>
>
>
Re: Build failed in Jenkins: Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui
#2101
Posted by Vinod Kone <vi...@gmail.com>.
hey adam can you triage this?
On Tue, Apr 29, 2014 at 11:09 PM, Apache Jenkins Server <
jenkins@builds.apache.org> 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 :
> master@67.195.138.8: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
> master@67.195.138.8: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
> master@67.195.138.8:58511
> I0430 06:08:49.459740 30348 sched.cpp:268] Authenticating with master
> master@67.195.138.8: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
> master@67.195.138.8:58511
> I0430 06:08:49.463973 30348 sched.cpp:323] Failed to authenticate with
> master master@67.195.138.8:58511: master changed
> I0430 06:08:49.463994 30348 sched.cpp:268] Authenticating with master
> master@67.195.138.8: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 master@67.195.138.8:58511
> I0430 06:08:49.464581 30348 sched.cpp:461] Sending registration request to
> master@67.195.138.8: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 :
> master@67.195.138.8: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
> master@67.195.138.8: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
>