Appears to be just the slowness of the build box (its disk):
I1028 02:38:46.849603 9003 coordinator.cpp:340] Coordinator attempting to
write TRUNCATE action at position 4
I1028 02:38:46.849669 9009 slave.cpp:2522] Received ping from
slave-observer(182)@67.195.81.187:33379
I1028 02:38:46.850030 8999 hierarchical_allocator_process.hpp:442] Added
slave 20141028-023846-3142697795-33379-8981-S0 (pomona.apache.org) with
cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and
cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] available)
I1028 02:38:46.850214 9004 replica.cpp:508] Replica received write request
for position 4
I1028 02:38:46.850265 8999 hierarchical_allocator_process.hpp:734]
Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on
slave 20141028-023846-3142697795-33379-8981-S0 to framework
20141028-023846-3142697795-33379-8981-0000
I../../src/tests/master_authorization_tests.cpp:244: Failure
Failed to wait 10secs for offers
../../src/tests/master_authorization_tests.cpp:238: Failure
Actual function call count doesn't match EXPECT_CALL(sched,
resourceOffers(&driver, _))...
Expected: to be called at least once
Actual: never called - unsatisfied and active`
1028 02:38:46.850360 8998 master.cpp:3086] Registered slave
20141028-023846-3142697795-33379-8981-S0 at slave(203)@67.195.81.187:33379 (
pomona.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024;
ports(*):[31000-32000]
I1028 02:38:46.850438 9009 slave.cpp:756] Registered with master
[email protected]:33379; given slave ID
20141028-023846-3142697795-33379-8981-S0
I1028 02:38:46.850680 9004 leveldb.cpp:343] Persisting action (16 bytes)
to leveldb took 440959ns
I1028 02:38:46.850715 8999 hierarchical_allocator_process.hpp:679]
Performed allocation for slave 20141028-023846-3142697795-33379-8981-S0 in
606258ns
I1028 02:38:51.348700 9000 master.cpp:120] No whitelist given. Advertising
offers for all slaves
I1028 02:39:07.113581 9004 replica.cpp:676] Persisted action at 4
I1028 02:39:07.114874 8996 status_update_manager.cpp:178] Resuming sending
status updates
I1028 02:39:07.115105 9009 slave.cpp:2522] Received ping from
slave-observer(182)@67.195.81.187:33379
I1028 02:39:07.115129 8999 hierarchical_allocator_process.hpp:659]
Performed allocation for 1 slaves in 235330ns
I1028 02:39:07.115429 8998 master.cpp:3795] Sending 1 offers to framework
20141028-023846-3142697795-33379-8981-0000 (default) at
[email protected]:33379
Master sent the offer after the 10sec deadline.
--
Jiang Yan Xu <[email protected]> @xujyan <http://twitter.com/xujyan>
On Mon, Oct 27, 2014 at 7:41 PM, Apache Jenkins Server <
[email protected]> wrote:
> See <
> https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/2498/changes
> >
>
> Changes:
>
> [tnachen] Added support for both 1.8 and earlier versions of svn library.
>
> ------------------------------------------
> [...truncated 64049 lines...]
> I1028 02:40:10.677944 8999 replica.cpp:508] Replica received write
> request for position 5
> I1028 02:40:10.678493 8999 leveldb.cpp:343] Persisting action (159 bytes)
> to leveldb took 518803ns
> I1028 02:40:10.678514 8999 replica.cpp:676] Persisted action at 5
> I1028 02:40:10.678982 9010 replica.cpp:655] Replica received learned
> notice for position 5
> I1028 02:40:10.679489 9010 leveldb.cpp:343] Persisting action (161 bytes)
> to leveldb took 485019ns
> I1028 02:40:10.679512 9010 replica.cpp:676] Persisted action at 5
> I1028 02:40:10.679532 9010 replica.cpp:661] Replica learned APPEND action
> at position 5
> I1028 02:40:10.680330 8997 registrar.cpp:490] Successfully updated the
> 'registry' in 0ns
> I1028 02:40:10.680462 9000 master.cpp:4527] Removed slave
> 20141028-024010-3142697795-33379-8981-S0 (pomona.apache.org)
> I1028 02:40:10.680486 9000 master.cpp:4545] Notifying framework
> 20141028-024010-3142697795-33379-8981-0000 (default) at
> [email protected]:33379 of
> lost slave 20141028-024010-3142697795-33379-8981-S0 (pomona.apache.org)
> after recovering
> I1028 02:40:10.680572 9005 log.cpp:699] Attempting to truncate the log to
> 5
> I1028 02:40:10.680577 8999 sched.cpp:686] Lost slave
> 20141028-024010-3142697795-33379-8981-S0
> I1028 02:40:10.680605 8999 sched.cpp:697] Scheduler::slaveLost took
> 16548ns
> I1028 02:40:10.680644 9003 coordinator.cpp:340] Coordinator attempting to
> write TRUNCATE action at position 6
> I1028 02:40:10.681084 8998 replica.cpp:508] Replica received write
> request for position 6
> I1028 02:40:10.681591 8998 leveldb.cpp:343] Persisting action (16 bytes)
> to leveldb took 485952ns
> I1028 02:40:10.681612 8998 replica.cpp:676] Persisted action at 6
> I1028 02:40:10.682003 9002 replica.cpp:655] Replica received learned
> notice for position 6
> I1028 02:40:10.682461 9002 leveldb.cpp:343] Persisting action (18 bytes)
> to leveldb took 441310ns
> I1028 02:40:10.682526 9002 leveldb.cpp:401] Deleting ~2 keys from leveldb
> took 42867ns
> I1028 02:40:10.682543 9002 replica.cpp:676] Persisted action at 6
> I1028 02:40:10.682562 9002 replica.cpp:661] Replica learned TRUNCATE
> action at position 6
> I1028 02:40:10.683429 8981 master.cpp:677] Master terminating
> I1028 02:40:10.683475 9000 sched.cpp:745] Stopping framework
> '20141028-024010-3142697795-33379-8981-0000'
> [ OK ] PartitionTest.PartitionedSlave (192 ms)
> [----------] 4 tests from PartitionTest (5540 ms total)
>
> [----------] 2 tests from FetcherTest
> [ RUN ] FetcherTest.FileURI
> Using temporary directory '/tmp/FetcherTest_FileURI_hD6W24'
> WARNING: Logging before InitGoogleLogging() is written to STDERR
> I1028 02:40:10.744001 14421 fetcher.cpp:76] Fetching URI
> 'file:///tmp/FetcherTest_FileURI_hD6W24/from/test'
> I1028 02:40:10.744141 14421 fetcher.cpp:179] Copying resource from
> '/tmp/FetcherTest_FileURI_hD6W24/from/test' to
> '/tmp/FetcherTest_FileURI_hD6W24'
> I1028 02:40:10.746620 14421 fetcher.cpp:255] Skipped extracting path
> '/tmp/FetcherTest_FileURI_hD6W24/test'
> [ OK ] FetcherTest.FileURI (126 ms)
> [ RUN ] FetcherTest.FileLocalhostURI
> Using temporary directory '/tmp/FetcherTest_FileLocalhostURI_YI2g60'
> WARNING: Logging before InitGoogleLogging() is written to STDERR
> I1028 02:40:10.870450 14438 fetcher.cpp:76] Fetching URI
> 'file://localhost/tmp/FetcherTest_FileLocalhostURI_YI2g60/from/test'
> I1028 02:40:10.870589 14438 fetcher.cpp:179] Copying resource from
> '/tmp/FetcherTest_FileLocalhostURI_YI2g60/from/test' to
> '/tmp/FetcherTest_FileLocalhostURI_YI2g60'
> I1028 02:40:10.873157 14438 fetcher.cpp:255] Skipped extracting path
> '/tmp/FetcherTest_FileLocalhostURI_YI2g60/test'
> [ OK ] FetcherTest.FileLocalhostURI (100 ms)
> [----------] 2 tests from FetcherTest (226 ms total)
>
> [----------] 1 test from WhitelistTest
> [ RUN ] WhitelistTest.WhitelistSlave
> Using temporary directory '/tmp/WhitelistTest_WhitelistSlave_NJdWpX'
> I1028 02:40:10.928699 8981 leveldb.cpp:176] Opened db in 3.23654ms
> I1028 02:40:10.929649 8981 leveldb.cpp:183] Compacted db in 912678ns
> I1028 02:40:10.929697 8981 leveldb.cpp:198] Created db iterator in 22119ns
> I1028 02:40:10.929713 8981 leveldb.cpp:204] Seeked to beginning of db in
> 2008ns
> I1028 02:40:10.929721 8981 leveldb.cpp:273] Iterated through 0 keys in
> the db in 345ns
> I1028 02:40:10.929764 8981 replica.cpp:741] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I1028 02:40:10.930315 9006 recover.cpp:437] Starting replica recovery
> I1028 02:40:10.930644 9006 recover.cpp:463] Replica is in EMPTY status
> I1028 02:40:10.931838 8998 replica.cpp:638] Replica in EMPTY status
> received a broadcasted recover request
> I1028 02:40:10.932387 9004 recover.cpp:188] Received a recover response
> from a replica in EMPTY status
> I1028 02:40:10.932492 8995 master.cpp:312] Master
> 20141028-024010-3142697795-33379-8981 (pomona.apache.org) started on
> 67.195.81.187:33379
> I1028 02:40:10.932548 8995 master.cpp:358] Master only allowing
> authenticated frameworks to register
> I1028 02:40:10.932564 8995 master.cpp:363] Master only allowing
> authenticated slaves to register
> I1028 02:40:10.932582 8995 credentials.hpp:36] Loading credentials for
> authentication from '/tmp/WhitelistTest_WhitelistSlave_NJdWpX/credentials'
> I1028 02:40:10.932842 8995 master.cpp:392] Authorization enabled
> I1028 02:40:10.932857 9008 recover.cpp:554] Updating replica status to
> STARTING
> I1028 02:40:10.933679 8998 leveldb.cpp:306] Persisting metadata (8 bytes)
> to leveldb took 691673ns
> I1028 02:40:10.933707 8998 replica.cpp:320] Persisted replica status to
> STARTING
> I1028 02:40:10.933733 8999 hierarchical_allocator_process.hpp:299]
> Initializing hierarchical allocator process with master :
> [email protected]:33379
> I1028 02:40:10.933895 8999 hierarchical_allocator_process.hpp:509]
> Updated slave white list: { dummy-slave, pomona.apache.org }
> I1028 02:40:10.934067 9004 recover.cpp:463] Replica is in STARTING status
> I1028 02:40:10.934599 8995 master.cpp:1242] The newly elected leader is
> [email protected]:33379 with id 20141028-024010-3142697795-33379-8981
> I1028 02:40:10.934623 8995 master.cpp:1255] Elected as the leading master!
> I1028 02:40:10.934638 8995 master.cpp:1073] Recovering from registrar
> I1028 02:40:10.934789 9000 registrar.cpp:313] Recovering registrar
> I1028 02:40:10.935426 8996 replica.cpp:638] Replica in STARTING status
> received a broadcasted recover request
> I1028 02:40:10.935852 9005 recover.cpp:188] Received a recover response
> from a replica in STARTING status
> I1028 02:40:10.936177 8996 recover.cpp:554] Updating replica status to
> VOTING
> I1028 02:40:10.936791 9000 leveldb.cpp:306] Persisting metadata (8 bytes)
> to leveldb took 475539ns
> I1028 02:40:10.936812 9000 replica.cpp:320] Persisted replica status to
> VOTING
> I1028 02:40:10.936905 9005 recover.cpp:568] Successfully joined the Paxos
> group
> I1028 02:40:10.937100 9005 recover.cpp:452] Recover process terminated
> I1028 02:40:10.937578 9001 log.cpp:656] Attempting to start the writer
> I1028 02:40:10.938859 8998 replica.cpp:474] Replica received implicit
> promise request with proposal 1
> I1028 02:40:10.939385 8998 leveldb.cpp:306] Persisting metadata (8 bytes)
> to leveldb took 498390ns
> I1028 02:40:10.939406 8998 replica.cpp:342] Persisted promised to 1
> I1028 02:40:10.939937 9005 coordinator.cpp:230] Coordinator attemping to
> fill missing position
> I1028 02:40:10.941053 9006 replica.cpp:375] Replica received explicit
> promise request for position 0 with proposal 2
> I1028 02:40:10.941553 9006 leveldb.cpp:343] Persisting action (8 bytes)
> to leveldb took 469261ns
> I1028 02:40:10.941576 9006 replica.cpp:676] Persisted action at 0
> I1028 02:40:10.942422 9001 replica.cpp:508] Replica received write
> request for position 0
> I1028 02:40:10.942484 9001 leveldb.cpp:438] Reading position from leveldb
> took 34404ns
> I1028 02:40:10.943001 9001 leveldb.cpp:343] Persisting action (14 bytes)
> to leveldb took 482578ns
> I1028 02:40:10.943022 9001 replica.cpp:676] Persisted action at 0
> I1028 02:40:10.943568 9000 replica.cpp:655] Replica received learned
> notice for position 0
> I1028 02:40:10.944077 9000 leveldb.cpp:343] Persisting action (16 bytes)
> to leveldb took 481656ns
> I1028 02:40:10.944097 9000 replica.cpp:676] Persisted action at 0
> I1028 02:40:10.944115 9000 replica.cpp:661] Replica learned NOP action at
> position 0
> I1028 02:40:10.944574 9007 log.cpp:672] Writer started with ending
> position 0
> I1028 02:40:10.945765 9010 leveldb.cpp:438] Reading position from leveldb
> took 30437ns
> I1028 02:40:10.948658 9008 registrar.cpp:346] Successfully fetched the
> registry (0B) in 13.8368ms
> I1028 02:40:10.948767 9008 registrar.cpp:445] Applied 1 operations in
> 19865ns; attempting to update the 'registry'
> I1028 02:40:10.951575 9001 log.cpp:680] Attempting to append 138 bytes to
> the log
> I1028 02:40:10.951761 9009 coordinator.cpp:340] Coordinator attempting to
> write APPEND action at position 1
> I1028 02:40:10.952478 9008 replica.cpp:508] Replica received write
> request for position 1
> I1028 02:40:10.952982 9008 leveldb.cpp:343] Persisting action (157 bytes)
> to leveldb took 469732ns
> I1028 02:40:10.953003 9008 replica.cpp:676] Persisted action at 1
> I1028 02:40:10.953568 9003 replica.cpp:655] Replica received learned
> notice for position 1
> I1028 02:40:10.954041 9003 leveldb.cpp:343] Persisting action (159 bytes)
> to leveldb took 449409ns
> I1028 02:40:10.954062 9003 replica.cpp:676] Persisted action at 1
> I1028 02:40:10.954082 9003 replica.cpp:661] Replica learned APPEND action
> at position 1
> I1028 02:40:10.954942 8998 registrar.cpp:490] Successfully updated the
> 'registry' in 6.126848ms
> I1028 02:40:10.955065 8998 registrar.cpp:376] Successfully recovered
> registrar
> I1028 02:40:10.955330 8997 log.cpp:699] Attempting to truncate the log to
> 1
> I1028 02:40:10.955370 9008 master.cpp:1100] Recovered 0 slaves from the
> Registry (100B) ; allowing 10mins for slaves to re-register
> I1028 02:40:10.955458 9007 coordinator.cpp:340] Coordinator attempting to
> write TRUNCATE action at position 2
> I1028 02:40:10.956040 8996 replica.cpp:508] Replica received write
> request for position 2
> I1028 02:40:10.956531 8996 leveldb.cpp:343] Persisting action (16 bytes)
> to leveldb took 460221ns
> I1028 02:40:10.956552 8996 replica.cpp:676] Persisted action at 2
> I1028 02:40:10.956998 9010 replica.cpp:655] Replica received learned
> notice for position 2
> I1028 02:40:10.957509 9010 leveldb.cpp:343] Persisting action (18 bytes)
> to leveldb took 489281ns
> I1028 02:40:10.957571 9010 leveldb.cpp:401] Deleting ~1 keys from leveldb
> took 39399ns
> I1028 02:40:10.957587 9010 replica.cpp:676] Persisted action at 2
> I1028 02:40:10.957607 9010 replica.cpp:661] Replica learned TRUNCATE
> action at position 2
> I1028 02:40:10.967023 8981 containerizer.cpp:95] Using isolation:
> posix/cpu,posix/mem
> I1028 02:40:10.970383 9006 slave.cpp:169] Slave started on 219)@
> 67.195.81.187:33379
> I1028 02:40:10.970423 9006 credentials.hpp:84] Loading credential for
> authentication from '/tmp/WhitelistTest_WhitelistSlave_G6rsQT/credential'
> I1028 02:40:10.970595 9006 slave.cpp:276] Slave using credential for:
> test-principal
> I1028 02:40:10.970990 9006 slave.cpp:289] Slave resources: cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I1028 02:40:10.971065 9006 slave.cpp:318] Slave hostname:
> pomona.apache.org
> I1028 02:40:10.971081 9006 slave.cpp:319] Slave checkpoint: false
> W1028 02:40:10.971092 9006 slave.cpp:321] Disabling checkpointing is
> deprecated and the --checkpoint flag will be removed in a future release.
> Please avoid using this flag
> I1028 02:40:10.971914 9004 state.cpp:33] Recovering state from
> '/tmp/WhitelistTest_WhitelistSlave_G6rsQT/meta'
> I1028 02:40:10.972105 9008 status_update_manager.cpp:197] Recovering
> status update manager
> I1028 02:40:10.972411 9002 containerizer.cpp:274] Recovering containerizer
> I1028 02:40:10.973233 9006 slave.cpp:3456] Finished recovery
> I1028 02:40:10.973760 9004 status_update_manager.cpp:171] Pausing sending
> status updates
> I1028 02:40:10.973768 9009 slave.cpp:602] New master detected at
> [email protected]:33379
> I1028 02:40:10.973795 9009 slave.cpp:665] Authenticating with master
> [email protected]:33379
> I1028 02:40:10.973908 9009 slave.cpp:638] Detecting new master
> I1028 02:40:10.973979 9002 authenticatee.hpp:133] Creating new client
> SASL connection
> I1028 02:40:10.974153 9000 master.cpp:3853] Authenticating slave(219)@
> 67.195.81.187:33379
> I1028 02:40:10.974333 9003 authenticator.hpp:161] Creating new server
> SASL connection
> I1028 02:40:10.974464 8995 authenticatee.hpp:224] Received SASL
> authentication mechanisms: CRAM-MD5
> I1028 02:40:10.974495 8995 authenticatee.hpp:250] Attempting to
> authenticate with mechanism 'CRAM-MD5'
> I1028 02:40:10.974594 9004 authenticator.hpp:267] Received SASL
> authentication start
> I1028 02:40:10.974644 9004 authenticator.hpp:389] Authentication requires
> more steps
> I1028 02:40:10.974710 9004 authenticatee.hpp:270] Received SASL
> authentication step
> I1028 02:40:10.974820 9009 authenticator.hpp:295] Received SASL
> authentication step
> I1028 02:40:10.974848 9009 auxprop.cpp:81] Request to lookup properties
> for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: '
> pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I1028 02:40:10.974858 9009 auxprop.cpp:153] Looking up auxiliary property
> '*userPassword'
> I1028 02:40:10.974891 9009 auxprop.cpp:153] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I1028 02:40:10.974911 9009 auxprop.cpp:81] Request to lookup properties
> for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: '
> pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I1028 02:40:10.974920 9009 auxprop.cpp:103] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I1028 02:40:10.974926 9009 auxprop.cpp:103] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I1028 02:40:10.974941 9009 authenticator.hpp:381] Authentication success
> I1028 02:40:10.975005 9010 authenticatee.hpp:310] Authentication success
> I1028 02:40:10.975028 9004 master.cpp:3893] Successfully authenticated
> principal 'test-principal' at slave(219)@67.195.81.187:33379
> I1028 02:40:10.975214 8996 slave.cpp:722] Successfully authenticated with
> master [email protected]:33379
> I1028 02:40:10.975388 8996 slave.cpp:1050] Will retry registration in
> 1.290111ms if necessary
> I1028 02:40:10.975553 9008 master.cpp:3032] Registering slave at
> slave(219)@67.195.81.187:33379 (pomona.apache.org) with id
> 20141028-024010-3142697795-33379-8981-S0
> I1028 02:40:10.975935 9010 registrar.cpp:445] Applied 1 operations in
> 56678ns; attempting to update the 'registry'
> I1028 02:40:10.976523 8981 sched.cpp:137] Version: 0.21.0
> I1028 02:40:10.976923 9008 sched.cpp:233] New master detected at
> [email protected]:33379
> I1028 02:40:10.976948 9008 sched.cpp:283] Authenticating with master
> [email protected]:33379
> I1028 02:40:10.977097 9000 authenticatee.hpp:133] Creating new client
> SASL connection
> I1028 02:40:10.977262 8996 master.cpp:3853] Authenticating
> [email protected]:33379
> I1028 02:40:10.977496 9002 authenticator.hpp:161] Creating new server
> SASL connection
> I1028 02:40:10.977607 8997 authenticatee.hpp:224] Received SASL
> authentication mechanisms: CRAM-MD5
> I1028 02:40:10.977638 8997 authenticatee.hpp:250] Attempting to
> authenticate with mechanism 'CRAM-MD5'
> I1028 02:40:10.977700 8997 authenticator.hpp:267] Received SASL
> authentication start
> I1028 02:40:10.977752 8997 authenticator.hpp:389] Authentication requires
> more steps
> I1028 02:40:10.977728 9008 slave.cpp:1050] Will retry registration in
> 12.292529ms if necessary
> I1028 02:40:10.977826 8997 authenticatee.hpp:270] Received SASL
> authentication step
> I1028 02:40:10.977835 9006 master.cpp:3020] Ignoring register slave
> message from slave(219)@67.195.81.187:33379 (pomona.apache.org) as
> admission is already in progress
> I1028 02:40:10.977910 9006 authenticator.hpp:295] Received SASL
> authentication step
> I1028 02:40:10.977926 9006 auxprop.cpp:81] Request to lookup properties
> for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: '
> pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I1028 02:40:10.977932 9006 auxprop.cpp:153] Looking up auxiliary property
> '*userPassword'
> I1028 02:40:10.977952 9006 auxprop.cpp:153] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I1028 02:40:10.977965 9006 auxprop.cpp:81] Request to lookup properties
> for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: '
> pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I1028 02:40:10.977972 9006 auxprop.cpp:103] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I1028 02:40:10.977975 9006 auxprop.cpp:103] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I1028 02:40:10.977985 9006 authenticator.hpp:381] Authentication success
> I1028 02:40:10.978032 9000 authenticatee.hpp:310] Authentication success
> I1028 02:40:10.978049 9008 master.cpp:3893] Successfully authenticated
> principal 'test-principal' at
> [email protected]:33379
> I1028 02:40:10.978149 8997 sched.cpp:357] Successfully authenticated with
> master [email protected]:33379
> I1028 02:40:10.978164 8997 sched.cpp:476] Sending registration request to
> [email protected]:33379
> I1028 02:40:10.978255 9001 master.cpp:1362] Received registration request
> for framework 'default' at
> [email protected]:33379
> I1028 02:40:10.978371 9001 master.cpp:1321] Authorizing framework
> principal 'test-principal' to receive offers for role '*'
> I1028 02:40:10.978667 9000 log.cpp:680] Attempting to append 314 bytes to
> the log
> I1028 02:40:10.978674 9001 master.cpp:1426] Registering framework
> 20141028-024010-3142697795-33379-8981-0000 (default) at
> [email protected]:33379
> I1028 02:40:10.978746 9006 coordinator.cpp:340] Coordinator attempting to
> write APPEND action at position 3
> I1028 02:40:10.978869 8999 hierarchical_allocator_process.hpp:329] Added
> framework 20141028-024010-3142697795-33379-8981-0000
> I1028 02:40:10.978888 8999 hierarchical_allocator_process.hpp:697] No
> resources available to allocate!
> I1028 02:40:10.978899 8999 hierarchical_allocator_process.hpp:659]
> Performed allocation for 0 slaves in 14781ns
> I1028 02:40:10.978937 9002 sched.cpp:407] Framework registered with
> 20141028-024010-3142697795-33379-8981-0000
> I1028 02:40:10.978968 9002 sched.cpp:421] Scheduler::registered took 17us
> I1028 02:40:10.979248 8995 replica.cpp:508] Replica received write
> request for position 3
> I1028 02:40:10.979773 8995 leveldb.cpp:343] Persisting action (333 bytes)
> to leveldb took 506869ns
> I1028 02:40:10.979789 8995 replica.cpp:676] Persisted action at 3
> I1028 02:40:10.980105 9002 replica.cpp:655] Replica received learned
> notice for position 3
> I1028 02:40:10.980588 9002 leveldb.cpp:343] Persisting action (335 bytes)
> to leveldb took 464715ns
> I1028 02:40:10.980603 9002 replica.cpp:676] Persisted action at 3
> I1028 02:40:10.980617 9002 replica.cpp:661] Replica learned APPEND action
> at position 3
> I1028 02:40:10.981269 9005 registrar.cpp:490] Successfully updated the
> 'registry' in 5.2928ms
> I1028 02:40:10.981567 8998 log.cpp:699] Attempting to truncate the log to
> 3
> I1028 02:40:10.981647 8996 coordinator.cpp:340] Coordinator attempting to
> write TRUNCATE action at position 4
> I1028 02:40:10.981667 9007 slave.cpp:2522] Received ping from
> slave-observer(198)@67.195.81.187:33379
> I1028 02:40:10.981734 9002 master.cpp:3086] Registered slave
> 20141028-024010-3142697795-33379-8981-S0 at slave(219)@67.195.81.187:33379
> (pomona.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000]
> I1028 02:40:10.981776 9001 slave.cpp:756] Registered with master
> [email protected]:33379; given slave ID
> 20141028-024010-3142697795-33379-8981-S0
> I1028 02:40:10.981833 9009 status_update_manager.cpp:178] Resuming
> sending status updates
> I1028 02:40:10.981852 9004 hierarchical_allocator_process.hpp:442] Added
> slave 20141028-024010-3142697795-33379-8981-S0 (pomona.apache.org) with
> cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and
> cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] available)
> I1028 02:40:10.981999 9004 hierarchical_allocator_process.hpp:734]
> Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on
> slave 20141028-024010-3142697795-33379-8981-S0 to framework
> 20141028-024010-3142697795-33379-8981-0000
> I1028 02:40:10.982089 8996 replica.cpp:508] Replica received write
> request for position 4
> I1028 02:40:10.982247 9004 hierarchical_allocator_process.hpp:679]
> Performed allocation for slave 20141028-024010-3142697795-33379-8981-S0 in
> 341173ns
> I1028 02:40:10.982475 8998 master.cpp:3795] Sending 1 offers to framework
> 20141028-024010-3142697795-33379-8981-0000 (default) at
> [email protected]:33379
> I1028 02:40:10.982620 8996 leveldb.cpp:343] Persisting action (16 bytes)
> to leveldb took 511211ns
> I1028 02:40:11.128798 8996 replica.cpp:676] Persisted action at 4
> I1028 02:40:11.129113 8997 sched.cpp:544] Scheduler::resourceOffers took
> 74255ns
> I1028 02:40:11.129304 9003 replica.cpp:655] Replica received learned
> notice for position 4
> I1028 02:40:11.129359 8981 master.cpp:677] Master terminating
> I1028 02:40:11.129387 8999 sched.cpp:745] Stopping framework
> '20141028-024010-3142697795-33379-8981-0000'
> I1028 02:40:11.129740 9006 slave.cpp:2607] [email protected]:33379
> exited
> W1028 02:40:11.129758 9006 slave.cpp:2610] Master disconnected! Waiting
> for a new master to be elected
> I1028 02:40:11.129793 9003 leveldb.cpp:343] Persisting action (18 bytes)
> to leveldb took 473718ns
> I1028 02:40:11.129837 9003 leveldb.cpp:401] Deleting ~2 keys from leveldb
> took 28461ns
> I1028 02:40:11.129849 9003 replica.cpp:676] Persisted action at 4
> I1028 02:40:11.129863 9003 replica.cpp:661] Replica learned TRUNCATE
> action at position 4
> I1028 02:40:11.132486 8981 slave.cpp:484] Slave terminating
> [ OK ] WhitelistTest.WhitelistSlave (211 ms)
> [----------] 1 test from WhitelistTest (211 ms total)
>
> [----------] Global test environment tear-down
> [==========] 408 tests from 63 test cases ran. (340939 ms total)
> [ PASSED ] 407 tests.
> [ FAILED ] 1 test, listed below:
> [ FAILED ] MasterAuthorizationTest.KillTask
>
> 1 FAILED TEST
> YOU HAVE 5 DISABLED TESTS
>
> make[3]: *** [check-local] Error 1
> 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
> Test finished
> Exit status: 2
> Build step 'Execute shell' marked build as failure
> Recording test results
>
