Committed a fix here:
commit 444c60beac5625e22dac99a059d782e662379091
Author: Benjamin Mahler <bmah...@twitter.com>
Date: Tue Jul 29 16:00:57 2014 -0700
Fixed a flaky slave recovery test.
diff --git a/src/tests/slave_recovery_tests.cpp
b/src/tests/slave_recovery_tests.cpp
index d024bd9..68ea3a2 100644
--- a/src/tests/slave_recovery_tests.cpp
+++ b/src/tests/slave_recovery_tests.cpp
@@ -2439,6 +2439,9 @@ TYPED_TEST(SlaveRecoveryTest, SchedulerFailover)
Future<Nothing> _recover = FUTURE_DISPATCH(_, &Slave::_recover);
+ Future<ReregisterExecutorMessage> reregisterExecutorMessage =
+ FUTURE_PROTOBUF(ReregisterExecutorMessage(), _, _);
+
Future<SlaveReregisteredMessage> slaveReregisteredMessage =
FUTURE_PROTOBUF(SlaveReregisteredMessage(), _, _);
@@ -2453,6 +2456,9 @@ TYPED_TEST(SlaveRecoveryTest, SchedulerFailover)
AWAIT_READY(_recover);
+ // Wait for the executor to re-register.
+ AWAIT_READY(reregisterExecutorMessage);
+
Clock::settle(); // Wait for slave to schedule reregister timeout.
Clock::advance(EXECUTOR_REREGISTER_TIMEOUT);
On Tue, Jul 29, 2014 at 2:49 PM, Apache Jenkins Server <
jenk...@builds.apache.org> wrote:
> See <
> https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/2282/changes
> >
>
> Changes:
>
> [yan] Fixed a bug that caused 'make dist' unable to patch leveldb.
>
> [bmahler] Fixed the master to accept a file:// based zk flag.
>
> ------------------------------------------
> [...truncated 54988 lines...]
> I0729 21:49:36.834485 23418 authenticator.hpp:376] Authentication success
> I0729 21:49:36.834508 23418 authenticatee.hpp:305] Authentication success
> I0729 21:49:36.834530 23418 master.cpp:3544] Successfully authenticated
> principal 'test-principal' at slave(195)@140.211.11.27:60822
> I0729 21:49:36.834589 23418 slave.cpp:734] Successfully authenticated with
> master master@140.211.11.27:60822
> I0729 21:49:36.834619 23418 slave.cpp:972] Will retry registration in
> 15.198248ms if necessary
> I0729 21:49:36.834677 23418 master.cpp:2762] Registering slave at
> slave(195)@140.211.11.27:60822 (hemera.apache.org) with id
> 20140729-214936-453759884-60822-23165-0
> I0729 21:49:36.834776 23418 registrar.cpp:422] Attempting to update the
> 'registry'
> I0729 21:49:36.836351 23418 log.cpp:680] Attempting to append 332 bytes to
> the log
> I0729 21:49:36.836395 23418 coordinator.cpp:340] Coordinator attempting to
> write APPEND action at position 3
> I0729 21:49:36.836596 23418 replica.cpp:508] Replica received write
> request for position 3
> I0729 21:49:36.853652 23418 leveldb.cpp:343] Persisting action (351 bytes)
> to leveldb took 17.041964ms
> I0729 21:49:36.853672 23418 replica.cpp:676] Persisted action at 3
> I0729 21:49:36.853713 23441 slave.cpp:972] Will retry registration in
> 24.094095ms if necessary
> I0729 21:49:36.853734 23418 master.cpp:2750] Ignoring register slave
> message from slave(195)@140.211.11.27:60822 (hemera.apache.org) as
> admission is already in progress
> I0729 21:49:36.853864 23441 replica.cpp:655] Replica received learned
> notice for position 3
> I0729 21:49:36.869662 23441 leveldb.cpp:343] Persisting action (353 bytes)
> to leveldb took 15.781742ms
> I0729 21:49:36.869683 23441 replica.cpp:676] Persisted action at 3
> I0729 21:49:36.869691 23441 replica.cpp:661] Replica learned APPEND action
> at position 3
> I0729 21:49:36.869976 23441 registrar.cpp:479] Successfully updated
> 'registry'
> I0729 21:49:36.870048 23441 log.cpp:699] Attempting to truncate the log to
> 3
> I0729 21:49:36.870100 23441 master.cpp:2802] Registered slave
> 20140729-214936-453759884-60822-23165-0 at slave(195)@140.211.11.27:60822
> (hemera.apache.org)
> I0729 21:49:36.870111 23441 master.cpp:3972] Adding slave
> 20140729-214936-453759884-60822-23165-0 at slave(195)@140.211.11.27:60822
> (hemera.apache.org) with cpus(*):2; mem(*):1024; disk(*):127026;
> ports(*):[31000-32000]
> I0729 21:49:36.870205 23441 coordinator.cpp:340] Coordinator attempting to
> write TRUNCATE action at position 4
> I0729 21:49:36.870265 23441 slave.cpp:768] Registered with master
> master@140.211.11.27:60822; given slave ID
> 20140729-214936-453759884-60822-23165-0
> I0729 21:49:36.870368 23441 slave.cpp:2325] Received ping from
> slave-observer(163)@140.211.11.27:60822
> I0729 21:49:36.870425 23441 hierarchical_allocator_process.hpp:444] Added
> slave 20140729-214936-453759884-60822-23165-0 (hemera.apache.org) with
> cpus(*):2; mem(*):1024; disk(*):127026; ports(*):[31000-32000] (and
> cpus(*):2; mem(*):1024; disk(*):127026; ports(*):[31000-32000] available)
> I0729 21:49:36.870479 23441 hierarchical_allocator_process.hpp:750]
> Offering cpus(*):2; mem(*):1024; disk(*):127026; ports(*):[31000-32000] on
> slave 20140729-214936-453759884-60822-23165-0 to framework
> 20140729-214936-453759884-60822-23165-0000
> I0729 21:49:36.870581 23441 hierarchical_allocator_process.hpp:706]
> Performed allocation for slave 20140729-214936-453759884-60822-23165-0 in
> 123548ns
> I0729 21:49:36.870661 23441 master.hpp:816] Adding offer
> 20140729-214936-453759884-60822-23165-0 with resources cpus(*):2;
> mem(*):1024; disk(*):127026; ports(*):[31000-32000] on slave
> 20140729-214936-453759884-60822-23165-0 (hemera.apache.org)
> I0729 21:49:36.870702 23441 master.cpp:3451] Sending 1 offers to framework
> 20140729-214936-453759884-60822-23165-0000
> I0729 21:49:36.870931 23441 sched.cpp:546] Scheduler::resourceOffers took
> 130370ns
> I0729 21:49:36.871111 23441 master.hpp:826] Removing offer
> 20140729-214936-453759884-60822-23165-0 with resources cpus(*):2;
> mem(*):1024; disk(*):127026; ports(*):[31000-32000] on slave
> 20140729-214936-453759884-60822-23165-0 (hemera.apache.org)
> I0729 21:49:36.871161 23441 master.cpp:2125] Processing reply for offers:
> [ 20140729-214936-453759884-60822-23165-0 ] on slave
> 20140729-214936-453759884-60822-23165-0 at slave(195)@140.211.11.27:60822
> (hemera.apache.org) for framework
> 20140729-214936-453759884-60822-23165-0000
> I0729 21:49:36.871181 23441 master.cpp:2211] Authorizing framework
> principal 'test-principal' to launch task 0 as user 'jenkins'
> I0729 21:49:36.871446 23441 replica.cpp:508] Replica received write
> request for position 4
> I0729 21:49:36.873731 23420 master.hpp:788] Adding task 0 with resources
> cpus(*):1; mem(*):500 on slave 20140729-214936-453759884-60822-23165-0 (
> hemera.apache.org)
> I0729 21:49:36.873761 23420 master.cpp:2277] Launching task 0 of framework
> 20140729-214936-453759884-60822-23165-0000 with resources cpus(*):1;
> mem(*):500 on slave 20140729-214936-453759884-60822-23165-0 at slave(195)@
> 140.211.11.27:60822 (hemera.apache.org)
> I0729 21:49:36.873890 23420 slave.cpp:1003] Got assigned task 0 for
> framework 20140729-214936-453759884-60822-23165-0000
> I0729 21:49:36.874059 23420 slave.cpp:1113] Launching task 0 for framework
> 20140729-214936-453759884-60822-23165-0000
> I0729 21:49:36.876996 23420 exec.cpp:131] Version: 0.20.0
> I0729 21:49:36.877096 23420 slave.cpp:1223] Queuing task '0' for executor
> default of framework '20140729-214936-453759884-60822-23165-0000
> I0729 21:49:36.877140 23430 exec.cpp:181] Executor started at:
> executor(62)@140.211.11.27:60822 with pid 23165
> I0729 21:49:36.881748 23436 hierarchical_allocator_process.hpp:546]
> Framework 20140729-214936-453759884-60822-23165-0000 left cpus(*):1;
> mem(*):524; disk(*):127026; ports(*):[31000-32000] unused on slave
> 20140729-214936-453759884-60822-23165-0
> I0729 21:49:36.881837 23436 hierarchical_allocator_process.hpp:588]
> Framework 20140729-214936-453759884-60822-23165-0000 filtered slave
> 20140729-214936-453759884-60822-23165-0 for 5secs
> I0729 21:49:36.889657 23441 leveldb.cpp:343] Persisting action (16 bytes)
> to leveldb took 18.192211ms
> I0729 21:49:36.889677 23441 replica.cpp:676] Persisted action at 4
> I0729 21:49:36.889827 23441 replica.cpp:655] Replica received learned
> notice for position 4
> I0729 21:49:36.897675 23420 slave.cpp:2470] Monitoring executor 'default'
> of framework '20140729-214936-453759884-60822-23165-0000' in container
> 'c0c67c96-df20-4629-a452-a90a4dddbf00'
> I0729 21:49:36.897735 23420 slave.cpp:1734] Got registration for executor
> 'default' of framework 20140729-214936-453759884-60822-23165-0000
> I0729 21:49:36.897809 23420 slave.cpp:1853] Flushing queued task 0 for
> executor 'default' of framework 20140729-214936-453759884-60822-23165-0000
> I0729 21:49:36.897871 23420 slave.cpp:562] Successfully attached file
> '/tmp/AllocatorTest_0_SlaveReregistersFirst_p09RPE/slaves/20140729-214936-453759884-60822-23165-0/frameworks/20140729-214936-453759884-60822-23165-0000/executors/default/runs/c0c67c96-df20-4629-a452-a90a4dddbf00'
> I0729 21:49:36.897943 23420 exec.cpp:205] Executor registered on slave
> 20140729-214936-453759884-60822-23165-0
> I0729 21:49:36.899235 23420 exec.cpp:217] Executor::registered took 12044ns
> I0729 21:49:36.899283 23420 exec.cpp:292] Executor asked to run task '0'
> I0729 21:49:36.899309 23420 exec.cpp:301] Executor::launchTask took 18158ns
> I0729 21:49:36.900600 23420 exec.cpp:524] Executor sending status update
> TASK_RUNNING (UUID: 2e23a056-5546-4488-90eb-06c422d5eec9) for task 0 of
> framework 20140729-214936-453759884-60822-23165-0000
> I0729 21:49:36.900670 23420 slave.cpp:2088] Handling status update
> TASK_RUNNING (UUID: 2e23a056-5546-4488-90eb-06c422d5eec9) for task 0 of
> framework 20140729-214936-453759884-60822-23165-0000 from executor(62)@
> 140.211.11.27:60822
> I0729 21:49:36.900748 23420 status_update_manager.cpp:320] Received status
> update TASK_RUNNING (UUID: 2e23a056-5546-4488-90eb-06c422d5eec9) for task 0
> of framework 20140729-214936-453759884-60822-23165-0000
> I0729 21:49:36.900758 23420 status_update_manager.cpp:499] Creating
> StatusUpdate stream for task 0 of framework
> 20140729-214936-453759884-60822-23165-0000
> I0729 21:49:36.900807 23420 status_update_manager.cpp:373] Forwarding
> status update TASK_RUNNING (UUID: 2e23a056-5546-4488-90eb-06c422d5eec9) for
> task 0 of framework 20140729-214936-453759884-60822-23165-0000 to
> master@140.211.11.27:60822
> I0729 21:49:36.900902 23420 master.cpp:3131] Forwarding status update
> TASK_RUNNING (UUID: 2e23a056-5546-4488-90eb-06c422d5eec9) for task 0 of
> framework 20140729-214936-453759884-60822-23165-0000
> I0729 21:49:36.900933 23420 master.cpp:3097] Status update TASK_RUNNING
> (UUID: 2e23a056-5546-4488-90eb-06c422d5eec9) for task 0 of framework
> 20140729-214936-453759884-60822-23165-0000 from slave
> 20140729-214936-453759884-60822-23165-0 at slave(195)@140.211.11.27:60822
> (hemera.apache.org)
> I0729 21:49:36.900962 23420 slave.cpp:2246] Status update manager
> successfully handled status update TASK_RUNNING (UUID:
> 2e23a056-5546-4488-90eb-06c422d5eec9) for task 0 of framework
> 20140729-214936-453759884-60822-23165-0000
> I0729 21:49:36.900972 23420 slave.cpp:2252] Sending acknowledgement for
> status update TASK_RUNNING (UUID: 2e23a056-5546-4488-90eb-06c422d5eec9) for
> task 0 of framework 20140729-214936-453759884-60822-23165-0000 to
> executor(62)@140.211.11.27:60822
> I0729 21:49:36.901038 23420 sched.cpp:637] Scheduler::statusUpdate took
> 15050ns
> I0729 21:49:36.901072 23420 exec.cpp:338] Executor received status update
> acknowledgement 2e23a056-5546-4488-90eb-06c422d5eec9 for task 0 of
> framework 20140729-214936-453759884-60822-23165-0000
> I0729 21:49:36.901118 23420 master.cpp:2612] Forwarding status update
> acknowledgement 2e23a056-5546-4488-90eb-06c422d5eec9 for task 0 of
> framework 20140729-214936-453759884-60822-23165-0000 to slave
> 20140729-214936-453759884-60822-23165-0 at slave(195)@140.211.11.27:60822
> (hemera.apache.org)
> I0729 21:49:36.901202 23420 status_update_manager.cpp:398] Received status
> update acknowledgement (UUID: 2e23a056-5546-4488-90eb-06c422d5eec9) for
> task 0 of framework 20140729-214936-453759884-60822-23165-0000
> I0729 21:49:36.901319 23420 slave.cpp:1674] Status update manager
> successfully handled status update acknowledgement (UUID:
> 2e23a056-5546-4488-90eb-06c422d5eec9) for task 0 of framework
> 20140729-214936-453759884-60822-23165-0000
> I0729 21:49:36.904687 23441 leveldb.cpp:343] Persisting action (18 bytes)
> to leveldb took 14.837602ms
> I0729 21:49:36.904727 23441 leveldb.cpp:401] Deleting ~2 keys from leveldb
> took 20007ns
> I0729 21:49:36.904737 23441 replica.cpp:676] Persisted action at 4
> I0729 21:49:36.904745 23441 replica.cpp:661] Replica learned TRUNCATE
> action at position 4
> I0729 21:49:36.904913 23165 master.cpp:626] Master terminating
> I0729 21:49:36.904948 23165 master.hpp:806] Removing task 0 with resources
> cpus(*):1; mem(*):500 on slave 20140729-214936-453759884-60822-23165-0 (
> hemera.apache.org)
> W0729 21:49:36.904989 23165 master.cpp:4261] Removing task 0 of framework
> 20140729-214936-453759884-60822-23165-0000 and slave
> 20140729-214936-453759884-60822-23165-0 in non-terminal state TASK_RUNNING
> I0729 21:49:36.909679 23440 slave.cpp:2332] master@140.211.11.27:60822
> exited
> W0729 21:49:36.909695 23440 slave.cpp:2335] Master disconnected! Waiting
> for a new master to be elected
> I0729 21:49:36.953749 23165 leveldb.cpp:176] Opened db in 47.425831ms
> I0729 21:49:36.997776 23165 leveldb.cpp:183] Compacted db in 44.003898ms
> I0729 21:49:36.997900 23165 leveldb.cpp:198] Created db iterator in 3698ns
> I0729 21:49:36.997970 23165 leveldb.cpp:204] Seeked to beginning of db in
> 7269ns
> I0729 21:49:36.998051 23165 leveldb.cpp:273] Iterated through 3 keys in
> the db in 18164ns
> I0729 21:49:36.998121 23165 replica.cpp:741] Replica recovered with log
> positions 3 -> 4 with 0 holes and 0 unlearned
> I0729 21:49:37.000005 23428 master.cpp:289] Master
> 20140729-214936-453759884-60822-23165 (hemera.apache.org) started on
> 140.211.11.27:60822
> I0729 21:49:37.000035 23428 master.cpp:326] Master only allowing
> authenticated frameworks to register
> I0729 21:49:37.000041 23428 master.cpp:331] Master only allowing
> authenticated slaves to register
> I0729 21:49:37.000048 23428 credentials.hpp:36] Loading credentials for
> authentication from
> '/tmp/AllocatorTest_0_SlaveReregistersFirst_iMpTJU/credentials'
> I0729 21:49:37.000169 23428 master.cpp:360] Authorization enabled
> I0729 21:49:37.000643 23428 recover.cpp:425] Starting replica recovery
> I0729 21:49:37.000857 23437 master.cpp:123] No whitelist given.
> Advertising offers for all slaves
> I0729 21:49:37.001271 23428 recover.cpp:451] Replica is in VOTING status
> I0729 21:49:37.001327 23428 recover.cpp:440] Recover process terminated
> I0729 21:49:37.005776 23437 master.cpp:1129] The newly elected leader is
> master@140.211.11.27:60822 with id 20140729-214936-453759884-60822-23165
> I0729 21:49:37.005792 23437 master.cpp:1142] Elected as the leading master!
> I0729 21:49:37.005805 23437 master.cpp:960] Recovering from registrar
> I0729 21:49:37.005863 23437 registrar.cpp:313] Recovering registrar
> I0729 21:49:37.005961 23423 hierarchical_allocator_process.hpp:301]
> Initializing hierarchical allocator process with master :
> master@140.211.11.27:60822
> I0729 21:49:37.006075 23423 log.cpp:656] Attempting to start the writer
> I0729 21:49:37.006387 23428 replica.cpp:474] Replica received implicit
> promise request with proposal 2
> I0729 21:49:37.019157 23428 leveldb.cpp:306] Persisting metadata (8 bytes)
> to leveldb took 12.753413ms
> I0729 21:49:37.019183 23428 replica.cpp:342] Persisted promised to 2
> I0729 21:49:37.019361 23428 coordinator.cpp:230] Coordinator attemping to
> fill missing position
> I0729 21:49:37.019443 23428 log.cpp:672] Writer started with ending
> position 4
> I0729 21:49:37.019686 23428 leveldb.cpp:438] Reading position from leveldb
> took 24690ns
> I0729 21:49:37.019712 23428 leveldb.cpp:438] Reading position from leveldb
> took 9283ns
> I0729 21:49:37.019980 23428 registrar.cpp:346] Successfully fetched the
> registry (293B)
> I0729 21:49:37.020002 23428 registrar.cpp:422] Attempting to update the
> 'registry'
> I0729 21:49:37.021587 23428 log.cpp:680] Attempting to append 332 bytes to
> the log
> I0729 21:49:37.021628 23428 coordinator.cpp:340] Coordinator attempting to
> write APPEND action at position 5
> I0729 21:49:37.021858 23428 replica.cpp:508] Replica received write
> request for position 5
> I0729 21:49:37.035399 23428 leveldb.cpp:343] Persisting action (351 bytes)
> to leveldb took 13.524949ms
> I0729 21:49:37.035420 23428 replica.cpp:676] Persisted action at 5
> I0729 21:49:37.035612 23428 replica.cpp:655] Replica received learned
> notice for position 5
> I0729 21:49:37.057674 23428 leveldb.cpp:343] Persisting action (353 bytes)
> to leveldb took 22.046755ms
> I0729 21:49:37.057701 23428 replica.cpp:676] Persisted action at 5
> I0729 21:49:37.057710 23428 replica.cpp:661] Replica learned APPEND action
> at position 5
> I0729 21:49:37.058027 23428 registrar.cpp:479] Successfully updated
> 'registry'
> I0729 21:49:37.058078 23428 registrar.cpp:372] Successfully recovered
> registrar
> I0729 21:49:37.058143 23428 log.cpp:699] Attempting to truncate the log to
> 5
> I0729 21:49:37.058238 23428 master.cpp:987] Recovered 1 slaves from the
> Registry (293B) ; allowing 10mins for slaves to re-register
> I0729 21:49:37.058277 23428 coordinator.cpp:340] Coordinator attempting to
> write TRUNCATE action at position 6
> I0729 21:49:37.058511 23428 replica.cpp:508] Replica received write
> request for position 6
> I0729 21:49:37.071751 23428 leveldb.cpp:343] Persisting action (16 bytes)
> to leveldb took 13.22495ms
> I0729 21:49:37.071775 23428 replica.cpp:676] Persisted action at 6
> I0729 21:49:37.071974 23428 replica.cpp:655] Replica received learned
> notice for position 6
> I0729 21:49:37.083822 23428 leveldb.cpp:343] Persisting action (18 bytes)
> to leveldb took 11.833875ms
> I0729 21:49:37.083863 23428 leveldb.cpp:401] Deleting ~2 keys from leveldb
> took 18355ns
> I0729 21:49:37.083873 23428 replica.cpp:676] Persisted action at 6
> I0729 21:49:37.083881 23428 replica.cpp:661] Replica learned TRUNCATE
> action at position 6
> I0729 21:49:37.099376 23428 slave.cpp:601] New master detected at
> master@140.211.11.27:60822
> I0729 21:49:37.099405 23428 slave.cpp:677] Authenticating with master
> master@140.211.11.27:60822
> I0729 21:49:37.099448 23428 slave.cpp:650] Detecting new master
> I0729 21:49:37.099486 23428 status_update_manager.cpp:167] New master
> detected at master@140.211.11.27:60822
> I0729 21:49:37.099519 23428 authenticatee.hpp:128] Creating new client
> SASL connection
> I0729 21:49:37.099643 23428 master.cpp:3504] Authenticating slave(195)@
> 140.211.11.27:60822
> I0729 21:49:37.099715 23428 authenticator.hpp:156] Creating new server
> SASL connection
> I0729 21:49:37.099798 23428 authenticatee.hpp:219] Received SASL
> authentication mechanisms: CRAM-MD5
> I0729 21:49:37.099812 23428 authenticatee.hpp:245] Attempting to
> authenticate with mechanism 'CRAM-MD5'
> I0729 21:49:37.099835 23428 authenticator.hpp:262] Received SASL
> authentication start
> I0729 21:49:37.099869 23428 authenticator.hpp:384] Authentication requires
> more steps
> I0729 21:49:37.099892 23428 authenticatee.hpp:265] Received SASL
> authentication step
> I0729 21:49:37.099921 23428 authenticator.hpp:290] Received SASL
> authentication step
> I0729 21:49:37.099935 23428 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
> I0729 21:49:37.099941 23428 auxprop.cpp:153] Looking up auxiliary property
> '*userPassword'
> I0729 21:49:37.099951 23428 auxprop.cpp:153] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0729 21:49:37.099958 23428 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
> I0729 21:49:37.099964 23428 auxprop.cpp:103] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0729 21:49:37.099969 23428 auxprop.cpp:103] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0729 21:49:37.099978 23428 authenticator.hpp:376] Authentication success
> I0729 21:49:37.100002 23428 authenticatee.hpp:305] Authentication success
> I0729 21:49:37.100021 23428 master.cpp:3544] Successfully authenticated
> principal 'test-principal' at slave(195)@140.211.11.27:60822
> I0729 21:49:37.100080 23428 slave.cpp:734] Successfully authenticated with
> master master@140.211.11.27:60822
> I0729 21:49:37.100152 23428 slave.cpp:972] Will retry registration in
> 11.433797ms if necessary
> I0729 21:49:37.100222 23428 master.cpp:2937] Re-registering slave
> 20140729-214936-453759884-60822-23165-0 at slave(195)@140.211.11.27:60822
> (hemera.apache.org)
> I0729 21:49:37.100366 23428 registrar.cpp:422] Attempting to update the
> 'registry'
> I0729 21:49:37.101912 23428 log.cpp:680] Attempting to append 332 bytes to
> the log
> I0729 21:49:37.101955 23428 coordinator.cpp:340] Coordinator attempting to
> write APPEND action at position 7
> I0729 21:49:37.102157 23428 replica.cpp:508] Replica received write
> request for position 7
> I0729 21:49:37.112546 23427 slave.cpp:972] Will retry registration in
> 2.150201ms if necessary
> I0729 21:49:37.112622 23427 master.cpp:2930] Ignoring re-register slave
> message from slave 20140729-214936-453759884-60822-23165-0 at slave(195)@
> 140.211.11.27:60822 (hemera.apache.org) as readmission is already in
> progress
> I0729 21:49:37.114987 23427 slave.cpp:972] Will retry registration in
> 70.279157ms if necessary
> I0729 21:49:37.115057 23427 master.cpp:2930] Ignoring re-register slave
> message from slave 20140729-214936-453759884-60822-23165-0 at slave(195)@
> 140.211.11.27:60822 (hemera.apache.org) as readmission is already in
> progress
> I0729 21:49:37.115897 23428 leveldb.cpp:343] Persisting action (351 bytes)
> to leveldb took 13.724569ms
> I0729 21:49:37.115918 23428 replica.cpp:676] Persisted action at 7
> I0729 21:49:37.116106 23428 replica.cpp:655] Replica received learned
> notice for position 7
> I0729 21:49:37.127997 23428 leveldb.cpp:343] Persisting action (353 bytes)
> to leveldb took 11.877137ms
> I0729 21:49:37.128021 23428 replica.cpp:676] Persisted action at 7
> I0729 21:49:37.128028 23428 replica.cpp:661] Replica learned APPEND action
> at position 7
> I0729 21:49:37.128324 23428 registrar.cpp:479] Successfully updated
> 'registry'
> I0729 21:49:37.128427 23428 log.cpp:699] Attempting to truncate the log to
> 7
> I0729 21:49:37.128480 23428 master.cpp:2988] Re-registered slave
> 20140729-214936-453759884-60822-23165-0 at slave(195)@140.211.11.27:60822
> (hemera.apache.org)
> I0729 21:49:37.128492 23428 master.cpp:3972] Adding slave
> 20140729-214936-453759884-60822-23165-0 at slave(195)@140.211.11.27:60822
> (hemera.apache.org) with cpus(*):2; mem(*):1024; disk(*):127026;
> ports(*):[31000-32000]
> I0729 21:49:37.128566 23428 master.hpp:788] Adding task 0 with resources
> cpus(*):1; mem(*):500 on slave 20140729-214936-453759884-60822-23165-0 (
> hemera.apache.org)
> W0729 21:49:37.128590 23428 master.cpp:4063] Possibly orphaned task 0 of
> framework 20140729-214936-453759884-60822-23165-0000 running on slave
> 20140729-214936-453759884-60822-23165-0 at slave(195)@140.211.11.27:60822
> (hemera.apache.org)
> I0729 21:49:37.128672 23428 coordinator.cpp:340] Coordinator attempting to
> write TRUNCATE action at position 8
> I0729 21:49:37.128734 23428 slave.cpp:818] Re-registered with master
> master@140.211.11.27:60822
> I0729 21:49:37.128855 23428 slave.cpp:2325] Received ping from
> slave-observer(164)@140.211.11.27:60822
> I0729 21:49:37.128926 23428 hierarchical_allocator_process.hpp:444] Added
> slave 20140729-214936-453759884-60822-23165-0 (hemera.apache.org) with
> cpus(*):2; mem(*):1024; disk(*):127026; ports(*):[31000-32000] (and
> cpus(*):1; mem(*):524; disk(*):127026; ports(*):[31000-32000] available)
> I0729 21:49:37.128962 23428 hierarchical_allocator_process.hpp:706]
> Performed allocation for slave 20140729-214936-453759884-60822-23165-0 in
> 8130ns
> I0729 21:49:37.129138 23428 replica.cpp:508] Replica received write
> request for position 8
> I0729 21:49:37.131124 23436 sched.cpp:229] Scheduler::disconnected took
> 8056ns
> I0729 21:49:37.131137 23436 sched.cpp:235] New master detected at
> master@140.211.11.27:60822
> I0729 21:49:37.131150 23436 sched.cpp:285] Authenticating with master
> master@140.211.11.27:60822
> I0729 21:49:37.131228 23436 authenticatee.hpp:128] Creating new client
> SASL connection
> I0729 21:49:37.131343 23436 master.cpp:3504] Authenticating
> scheduler-94956444-fee9-4b8a-af85-f9945690ee07@140.211.11.27:60822
> I0729 21:49:37.131417 23436 authenticator.hpp:156] Creating new server
> SASL connection
> I0729 21:49:37.131492 23436 authenticatee.hpp:219] Received SASL
> authentication mechanisms: CRAM-MD5
> I0729 21:49:37.131506 23436 authenticatee.hpp:245] Attempting to
> authenticate with mechanism 'CRAM-MD5'
> I0729 21:49:37.131527 23436 authenticator.hpp:262] Received SASL
> authentication start
> I0729 21:49:37.131557 23436 authenticator.hpp:384] Authentication
> requires more steps
> I0729 21:49:37.131580 23436 authenticatee.hpp:265] Received SASL
> authentication step
> I0729 21:49:37.131609 23436 authenticator.hpp:290] Received SASL
> authentication step
> I0729 21:49:37.131620 23436 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
> I0729 21:49:37.131628 23436 auxprop.cpp:153] Looking up auxiliary
> property '*userPassword'
> I0729 21:49:37.131635 23436 auxprop.cpp:153] Looking up auxiliary
> property '*cmusaslsecretCRAM-MD5'
> I0729 21:49:37.131644 23436 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
> I0729 21:49:37.131649 23436 auxprop.cpp:103] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0729 21:49:37.131654 23436 auxprop.cpp:103] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0729 21:49:37.131664 23436 authenticator.hpp:376] Authentication success
> I0729 21:49:37.131686 23436 authenticatee.hpp:305] Authentication success
> I0729 21:49:37.131705 23436 master.cpp:3544] Successfully authenticated
> principal 'test-principal' at
> scheduler-94956444-fee9-4b8a-af85-f9945690ee07@140.211.11.27:60822
> I0729 21:49:37.131762 23436 sched.cpp:359] Successfully authenticated
> with master master@140.211.11.27:60822
> I0729 21:49:37.131773 23436 sched.cpp:478] Sending registration request
> to master@140.211.11.27:60822
> I0729 21:49:37.131814 23436 master.cpp:1356] Received re-registration
> request from framework 20140729-214936-453759884-60822-23165-0000 at
> scheduler-94956444-fee9-4b8a-af85-f9945690ee07@140.211.11.27:60822
> I0729 21:49:37.131832 23436 master.cpp:1208] Authorizing framework
> principal 'test-principal' to receive offers for role '*'
> I0729 21:49:37.131916 23436 master.cpp:1407] Re-registering framework
> 20140729-214936-453759884-60822-23165-0000 at
> scheduler-94956444-fee9-4b8a-af85-f9945690ee07@140.211.11.27:60822
> I0729 21:49:37.132053 23436 sched.cpp:409] Framework registered with
> 20140729-214936-453759884-60822-23165-0000
> I0729 21:49:37.132072 23436 sched.cpp:423] Scheduler::registered took
> 8566ns
> I0729 21:49:37.132170 23436 slave.cpp:1584] Updating framework
> 20140729-214936-453759884-60822-23165-0000 pid to
> scheduler-94956444-fee9-4b8a-af85-f9945690ee07@140.211.11.27:60822
> I0729 21:49:37.132230 23436 hierarchical_allocator_process.hpp:331] Added
> framework 20140729-214936-453759884-60822-23165-0000
> I0729 21:49:37.132266 23436 hierarchical_allocator_process.hpp:750]
> Offering cpus(*):1; mem(*):524; disk(*):127026; ports(*):[31000-32000] on
> slave 20140729-214936-453759884-60822-23165-0 to framework
> 20140729-214936-453759884-60822-23165-0000
> I0729 21:49:37.132380 23436 hierarchical_allocator_process.hpp:686]
> Performed allocation for 1 slaves in 137410ns
> I0729 21:49:37.132441 23436 master.hpp:816] Adding offer
> 20140729-214936-453759884-60822-23165-0 with resources cpus(*):1;
> mem(*):524; disk(*):127026; ports(*):[31000-32000] on slave
> 20140729-214936-453759884-60822-23165-0 (hemera.apache.org)
> I0729 21:49:37.132484 23436 master.cpp:3451] Sending 1 offers to framework
> 20140729-214936-453759884-60822-23165-0000
> I0729 21:49:37.132576 23436 sched.cpp:546] Scheduler::resourceOffers took
> 18628ns
> I0729 21:49:37.133805 23165 master.cpp:626] Master terminating
> I0729 21:49:37.133855 23165 master.hpp:806] Removing task 0 with resources
> cpus(*):1; mem(*):500 on slave 20140729-214936-453759884-60822-23165-0 (
> hemera.apache.org)
> W0729 21:49:37.133896 23165 master.cpp:4261] Removing task 0 of framework
> 20140729-214936-453759884-60822-23165-0000 and slave
> 20140729-214936-453759884-60822-23165-0 in non-terminal state TASK_RUNNING
> I0729 21:49:37.133930 23165 master.hpp:826] Removing offer
> 20140729-214936-453759884-60822-23165-0 with resources cpus(*):1;
> mem(*):524; disk(*):127026; ports(*):[31000-32000] on slave
> 20140729-214936-453759884-60822-23165-0 (hemera.apache.org)
> I0729 21:49:37.137677 23436 sched.cpp:747] Stopping framework
> '20140729-214936-453759884-60822-23165-0000'
> I0729 21:49:37.137723 23436 slave.cpp:2332] master@140.211.11.27:60822
> exited
> W0729 21:49:37.137733 23436 slave.cpp:2335] Master disconnected! Waiting
> for a new master to be elected
> I0729 21:49:37.144139 23428 leveldb.cpp:343] Persisting action (16 bytes)
> to leveldb took 14.921098ms
> I0729 21:49:37.144162 23428 replica.cpp:676] Persisted action at 8
> I0729 21:49:37.162089 23165 slave.cpp:485] Slave terminating
> I0729 21:49:37.162175 23165 slave.cpp:1407] Asked to shut down framework
> 20140729-214936-453759884-60822-23165-0000 by @0.0.0.0:0
> I0729 21:49:37.162240 23165 slave.cpp:1432] Shutting down framework
> 20140729-214936-453759884-60822-23165-0000
> I0729 21:49:37.162299 23165 slave.cpp:2808] Shutting down executor
> 'default' of framework 20140729-214936-453759884-60822-23165-0000
> [ OK ] AllocatorTest/0.SlaveReregistersFirst (585 ms)
> [----------] 12 tests from AllocatorTest/0 (5748 ms total)
>
> [----------] Global test environment tear-down
> [==========] 351 tests from 57 test cases ran. (249674 ms total)
> [ PASSED ] 350 tests.
> [ FAILED ] 1 test, listed below:
> [ FAILED ] SlaveRecoveryTest/0.SchedulerFailover, where TypeParam =
> mesos::internal::slave::MesosContainerizer
>
> 1 FAILED TEST
> YOU HAVE 3 DISABLED TESTS
>
> make[3]: *** [check-local] Error 1
> 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
> Build step 'Execute shell' marked build as failure
>
