Fix is here: https://reviews.apache.org/r/15955
On Mon, Dec 2, 2013 at 6:44 PM, Apache Jenkins Server < [email protected]> wrote: > See < > https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/1511/changes > > > > Changes: > > [bmahler] Fixed flaky FaultToleranceTest.SchedulerFailoverStatusUpdate. > > [bmahler] Fixed ./bootstrap to handle AUTOMAKE and ACLOCAL environment > > ------------------------------------------ > [...truncated 22484 lines...] > 2013-12-03 02:44:52,982:22860(0x2b4e51175700):ZOO_INFO@check_events@1632: > session establishment complete on server [127.0.0.1:52432], > sessionId=0x142b65803d50006, negotiated timeout=10000 > I1203 02:44:52.982332 22882 group.cpp:298] Trying to create path '/znode' > in ZooKeeper > 2013-12-03 02:44:52,982:22860(0x2b4e6c401700):ZOO_INFO@check_events@1632: > session establishment complete on server [127.0.0.1:52432], > sessionId=0x142b65803d50007, negotiated timeout=10000 > I1203 02:44:52.982957 22885 group.cpp:298] Trying to create path '/znode' > in ZooKeeper > 2013-12-03 02:44:52,982:22860(0x2b4e6c200700):ZOO_INFO@check_events@1632: > session establishment complete on server [127.0.0.1:52432], > sessionId=0x142b65803d50008, negotiated timeout=10000 > I1203 02:44:52.983249 22884 group.cpp:298] Trying to create path '/znode' > in ZooKeeper > 2013-12-03 02:44:52,983:22860(0x2b4e50d73700):ZOO_INFO@check_events@1632: > session establishment complete on server [127.0.0.1:52432], > sessionId=0x142b65803d50009, negotiated timeout=10000 > I1203 02:44:52.983445 22883 group.cpp:298] Trying to create path '/znode' > in ZooKeeper > I1203 02:44:53.005831 22880 contender.cpp:203] New candidate (id='4', > data='[email protected]:43939') has entered the contest for leadership > I1203 02:44:53.006005 22882 detector.cpp:130] Detected a new leader > (id='4') > I1203 02:44:53.006077 22882 group.cpp:540] Trying to get > '/znode/0000000004' in ZooKeeper > I1203 02:44:53.006232 22884 detector.cpp:130] Detected a new leader > (id='4') > I1203 02:44:53.006309 22881 group.cpp:540] Trying to get > '/znode/0000000004' in ZooKeeper > I1203 02:44:53.006372 22883 detector.cpp:130] Detected a new leader > (id='4') > I1203 02:44:53.006446 22883 group.cpp:540] Trying to get > '/znode/0000000004' in ZooKeeper > I1203 02:44:53.006763 22882 detector.cpp:322] A new leading master (UPID= > [email protected]:43939) is detected > I1203 02:44:53.006798 22882 master.cpp:743] The newly elected leader is > [email protected]:43939 > I1203 02:44:53.006808 22882 master.cpp:747] Elected as the leading master! > I1203 02:44:53.006984 22881 detector.cpp:322] A new leading master (UPID= > [email protected]:43939) is detected > I1203 02:44:53.007063 22879 sched.cpp:207] New master detected at > [email protected]:43939 > I1203 02:44:53.007083 22883 detector.cpp:322] A new leading master (UPID= > [email protected]:43939) is detected > I1203 02:44:53.007097 22879 sched.cpp:260] Authenticating with master > [email protected]:43939 > I1203 02:44:53.007114 22883 slave.cpp:497] New master detected at > [email protected]:43939 > I1203 02:44:53.007155 22879 sched.cpp:229] Detecting new master > I1203 02:44:53.007163 22883 slave.cpp:524] Detecting new master > I1203 02:44:53.007161 22881 authenticatee.hpp:124] Creating new client > SASL connection > I1203 02:44:53.007160 22880 status_update_manager.cpp:160] New master > detected at [email protected]:43939 > I1203 02:44:53.007225 22879 master.cpp:1363] Attempting to register slave > on vesta.apache.org at slave(136)@67.195.138.9:43939 > I1203 02:44:53.007247 22879 master.cpp:2618] Adding slave > 201312030244-160088899-43939-22860-0 at vesta.apache.org with cpus(*):2; > mem(*):1024; disk(*):1.38501e+06; ports(*):[31000-32000] > I1203 02:44:53.007310 22880 slave.cpp:542] Registered with master > [email protected]:43939; given slave ID > 201312030244-160088899-43939-22860-0 > I1203 02:44:53.007385 22879 master.cpp:1839] Authenticating framework at > scheduler(131)@67.195.138.9:43939 > I1203 02:44:53.007417 22881 hierarchical_allocator_process.hpp:445] Added > slave 201312030244-160088899-43939-22860-0 (vesta.apache.org) with > cpus(*):2; mem(*):1024; disk(*):1.38501e+06; ports(*):[31000-32000] (and > cpus(*):2; mem(*):1024; disk(*):1.38501e+06; ports(*):[31000-32000] > available) > I1203 02:44:53.007472 22880 authenticator.hpp:140] Creating new server > SASL connection > I1203 02:44:53.007488 22881 hierarchical_allocator_process.hpp:708] > Performed allocation for slave 201312030244-160088899-43939-22860-0 in > 10832ns > I1203 02:44:53.007556 22885 authenticatee.hpp:212] Received SASL > authentication mechanisms: CRAM-MD5 > I1203 02:44:53.007581 22885 authenticatee.hpp:238] Attempting to > authenticate with mechanism 'CRAM-MD5' > I1203 02:44:53.007606 22885 authenticator.hpp:243] Received SASL > authentication start > I1203 02:44:53.007673 22885 authenticator.hpp:325] Authentication requires > more steps > I1203 02:44:53.007701 22885 authenticatee.hpp:258] Received SASL > authentication step > I1203 02:44:53.007755 22883 authenticator.hpp:271] Received SASL > authentication step > I1203 02:44:53.007782 22883 auxprop.cpp:81] Request to lookup properties > for user: 'test-principal' realm: 'vesta.apache.org' server FQDN: ' > vesta.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false > SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false > I1203 02:44:53.007791 22883 auxprop.cpp:153] Looking up auxiliary property > '*userPassword' > I1203 02:44:53.007817 22883 auxprop.cpp:153] Looking up auxiliary property > '*cmusaslsecretCRAM-MD5' > I1203 02:44:53.007827 22883 auxprop.cpp:81] Request to lookup properties > for user: 'test-principal' realm: 'vesta.apache.org' server FQDN: ' > vesta.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false > SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true > I1203 02:44:53.007833 22883 auxprop.cpp:103] Skipping auxiliary property > '*userPassword' since SASL_AUXPROP_AUTHZID == true > I1203 02:44:53.007838 22883 auxprop.cpp:103] Skipping auxiliary property > '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true > I1203 02:44:53.007849 22883 authenticator.hpp:317] Authentication success > I1203 02:44:53.007872 22885 authenticatee.hpp:298] Authentication success > I1203 02:44:53.007874 22883 master.cpp:1879] Successfully authenticated > framework at scheduler(131)@67.195.138.9:43939 > I1203 02:44:53.007933 22885 sched.cpp:334] Successfully authenticated with > master [email protected]:43939 > I1203 02:44:53.008028 22883 master.cpp:798] Received registration request > from scheduler(131)@67.195.138.9:43939 > I1203 02:44:53.008180 22883 master.cpp:816] Registering framework > 201312030244-160088899-43939-22860-0000 at scheduler(131)@ > 67.195.138.9:43939 > I1203 02:44:53.008249 22883 hierarchical_allocator_process.hpp:332] Added > framework 201312030244-160088899-43939-22860-0000 > I1203 02:44:53.008250 22880 sched.cpp:383] Framework registered with > 201312030244-160088899-43939-22860-0000 > I1203 02:44:53.008299 22880 sched.cpp:397] Scheduler::registered took > 15418ns > I1203 02:44:53.008308 22883 hierarchical_allocator_process.hpp:752] > Offering cpus(*):2; mem(*):1024; disk(*):1.38501e+06; > ports(*):[31000-32000] on slave 201312030244-160088899-43939-22860-0 to > framework 201312030244-160088899-43939-22860-0000 > I1203 02:44:53.008422 22883 hierarchical_allocator_process.hpp:688] > Performed allocation for 1 slaves in 148767ns > I1203 02:44:53.008467 22879 master.hpp:432] Adding offer > 201312030244-160088899-43939-22860-0 with resources cpus(*):2; mem(*):1024; > disk(*):1.38501e+06; ports(*):[31000-32000] on slave > 201312030244-160088899-43939-22860-0 (vesta.apache.org) > I1203 02:44:53.008523 22879 master.cpp:1800] Sending 1 offers to framework > 201312030244-160088899-43939-22860-0000 > I1203 02:44:53.008788 22881 sched.cpp:517] Scheduler::resourceOffers took > 155582ns > I1203 02:44:53.008908 22880 master.cpp:2131] Processing reply for offer > 201312030244-160088899-43939-22860-0 on slave > 201312030244-160088899-43939-22860-0 (vesta.apache.org) for framework > 201312030244-160088899-43939-22860-0000 > I1203 02:44:53.009011 22880 master.hpp:404] Adding task 0 with resources > cpus(*):1; mem(*):500 on slave 201312030244-160088899-43939-22860-0 ( > vesta.apache.org) > I1203 02:44:53.009043 22880 master.cpp:2255] Launching task 0 of framework > 201312030244-160088899-43939-22860-0000 with resources cpus(*):1; > mem(*):500 on slave 201312030244-160088899-43939-22860-0 (vesta.apache.org > ) > I1203 02:44:53.009102 22881 slave.cpp:722] Got assigned task 0 for > framework 201312030244-160088899-43939-22860-0000 > I1203 02:44:53.009186 22885 hierarchical_allocator_process.hpp:547] > Framework 201312030244-160088899-43939-22860-0000 left cpus(*):1; > mem(*):524; disk(*):1.38501e+06; ports(*):[31000-32000] unused on slave > 201312030244-160088899-43939-22860-0 > I1203 02:44:53.009196 22880 master.hpp:442] Removing offer > 201312030244-160088899-43939-22860-0 with resources cpus(*):2; mem(*):1024; > disk(*):1.38501e+06; ports(*):[31000-32000] on slave > 201312030244-160088899-43939-22860-0 (vesta.apache.org) > I1203 02:44:53.009258 22881 slave.cpp:833] Launching task 0 for framework > 201312030244-160088899-43939-22860-0000 > I1203 02:44:53.009313 22885 hierarchical_allocator_process.hpp:590] > Framework 201312030244-160088899-43939-22860-0000 filtered slave > 201312030244-160088899-43939-22860-0 for 5secs > I1203 02:44:53.017907 22881 slave.cpp:943] Queuing task '0' for executor > default of framework '201312030244-160088899-43939-22860-0000 > I1203 02:44:53.017969 22884 slave.cpp:466] Successfully attached file > '/tmp/AllocatorZooKeeperTest_0_SlaveReregistersFirst_9EkAfR/slaves/201312030244-160088899-43939-22860-0/frameworks/201312030244-160088899-43939-22860-0000/executors/default/runs/98c4bbe4-27ca-49bc-af22-464fc139a0e5' > I1203 02:44:53.019251 22880 exec.cpp:178] Executor started at: > executor(45)@67.195.138.9:43939 with pid 22860 > I1203 02:44:53.019280 22882 slave.cpp:2078] Monitoring executor default of > framework 201312030244-160088899-43939-22860-0000 forked at pid 22860 > I1203 02:44:53.019347 22882 slave.cpp:1411] Got registration for executor > 'default' of framework 201312030244-160088899-43939-22860-0000 > I1203 02:44:53.019527 22882 slave.cpp:1532] Flushing queued task 0 for > executor 'default' of framework 201312030244-160088899-43939-22860-0000 > I1203 02:44:53.019542 22885 exec.cpp:202] Executor registered on slave > 201312030244-160088899-43939-22860-0 > I1203 02:44:53.020794 22885 exec.cpp:214] Executor::registered took 9768ns > I1203 02:44:53.020846 22885 exec.cpp:289] Executor asked to run task '0' > I1203 02:44:53.020889 22885 exec.cpp:298] Executor::launchTask took 27095ns > I1203 02:44:53.022076 22885 exec.cpp:521] Executor sending status update > TASK_RUNNING (UUID: ffc9611b-87f8-42f1-9a2b-d7286187ef04) for task 0 of > framework 201312030244-160088899-43939-22860-0000 > I1203 02:44:53.022141 22885 slave.cpp:1745] Handling status update > TASK_RUNNING (UUID: ffc9611b-87f8-42f1-9a2b-d7286187ef04) for task 0 of > framework 201312030244-160088899-43939-22860-0000 from executor(45)@ > 67.195.138.9:43939 > I1203 02:44:53.022234 22879 status_update_manager.cpp:312] Received status > update TASK_RUNNING (UUID: ffc9611b-87f8-42f1-9a2b-d7286187ef04) for task 0 > of framework 201312030244-160088899-43939-22860-0000 > I1203 02:44:53.022254 22879 status_update_manager.cpp:491] Creating > StatusUpdate stream for task 0 of framework > 201312030244-160088899-43939-22860-0000 > I1203 02:44:53.022326 22879 status_update_manager.cpp:365] Forwarding > status update TASK_RUNNING (UUID: ffc9611b-87f8-42f1-9a2b-d7286187ef04) for > task 0 of framework 201312030244-160088899-43939-22860-0000 to > [email protected]:43939 > I1203 02:44:53.022444 22885 master.cpp:1549] Status update TASK_RUNNING > (UUID: ffc9611b-87f8-42f1-9a2b-d7286187ef04) for task 0 of framework > 201312030244-160088899-43939-22860-0000 from slave(136)@67.195.138.9:43939 > I1203 02:44:53.022451 22881 slave.cpp:1864] Status update manager > successfully handled status update TASK_RUNNING (UUID: > ffc9611b-87f8-42f1-9a2b-d7286187ef04) for task 0 of framework > 201312030244-160088899-43939-22860-0000 > I1203 02:44:53.022472 22881 slave.cpp:1870] Sending acknowledgement for > status update TASK_RUNNING (UUID: ffc9611b-87f8-42f1-9a2b-d7286187ef04) for > task 0 of framework 201312030244-160088899-43939-22860-0000 to executor(45)@ > 67.195.138.9:43939 > I1203 02:44:53.022498 22879 sched.cpp:608] Scheduler::statusUpdate took > 29382ns > I1203 02:44:53.022550 22880 exec.cpp:335] Executor received status update > acknowledgement ffc9611b-87f8-42f1-9a2b-d7286187ef04 for task 0 of > framework 201312030244-160088899-43939-22860-0000 > I1203 02:44:53.022584 22880 status_update_manager.cpp:390] Received status > update acknowledgement (UUID: ffc9611b-87f8-42f1-9a2b-d7286187ef04) for > task 0 of framework 201312030244-160088899-43939-22860-0000 > I1203 02:44:53.022629 22880 slave.cpp:1351] Status update manager > successfully handled status update acknowledgement (UUID: > ffc9611b-87f8-42f1-9a2b-d7286187ef04) for task 0 of framework > 201312030244-160088899-43939-22860-0000 > I1203 02:44:53.022729 22860 master.cpp:553] Master terminating > I1203 02:44:53.022775 22860 master.cpp:209] Shutting down master > I1203 02:44:53.022793 22880 slave.cpp:1945] [email protected]:43939exited > W1203 02:44:53.022812 22880 slave.cpp:1948] Master disconnected! Waiting > for a new master to be elected > I1203 02:44:53.022814 22860 master.hpp:422] Removing task 0 with resources > cpus(*):1; mem(*):500 on slave 201312030244-160088899-43939-22860-0 ( > vesta.apache.org) > I1203 02:44:53.022912 22860 master.cpp:252] Removing slave > 201312030244-160088899-43939-22860-0 (vesta.apache.org) > I1203 02:44:53.022914 22884 hierarchical_allocator_process.hpp:637] > Recovered cpus(*):1; mem(*):500 (total allocatable: cpus(*):2; mem(*):1024; > disk(*):1.38501e+06; ports(*):[31000-32000]) on slave > 201312030244-160088899-43939-22860-0 from framework > 201312030244-160088899-43939-22860-0000 > I1203 02:44:53.179582 22882 contender.cpp:172] Now cancelling the > membership: 4 > I1203 02:44:53.179662 22882 group.cpp:496] Trying to remove > '/znode/0000000004' in ZooKeeper > 2013-12-03 02:44:53,189:22860(0x2b4d38e1d7c0):ZOO_INFO@zookeeper_close@2304: > Closing zookeeper sessionId=0x142b65803d50007 to [127.0.0.1:52432] > > I1203 02:44:53.189875 22883 detector.cpp:116] The current leader (id=4) is > lost > I1203 02:44:53.189889 22883 detector.cpp:138] No new leader is elected > after election > I1203 02:44:53.190060 22886 sched.cpp:201] Scheduler::disconnected took > 24110ns > I1203 02:44:53.190084 22886 sched.cpp:223] No master detected > I1203 02:44:53.190086 22884 detector.cpp:116] The current leader (id=4) > is lost > I1203 02:44:53.190090 22886 sched.cpp:229] Detecting new master > 2013-12-03 02:44:53,190:22860(0x2b4d38e1d7c0):ZOO_INFO@zookeeper_close@2304: > Closing zookeeper sessionId=0x142b65803d50006 to [127.0.0.1:52432] > > I1203 02:44:53.190116 22884 detector.cpp:138] No new leader is elected > after election > I1203 02:44:53.190389 22879 slave.cpp:518] Lost leading master > I1203 02:44:53.190403 22879 slave.cpp:524] Detecting new master > I1203 02:44:53.191231 22883 master.cpp:284] Master started on > 67.195.138.9:43939 > I1203 02:44:53.191269 22883 master.cpp:298] Master ID: > 201312030244-160088899-43939-22860 > I1203 02:44:53.191275 22883 master.cpp:301] Master only allowing > authenticated frameworks to register! > I1203 02:44:53.191618 22886 master.cpp:84] No whitelist given. Advertising > offers for all slaves > 2013-12-03 02:44:53,191:22860(0x2b4d39022700):ZOO_INFO@log_env@658: > Client environment:zookeeper.version=zookeeper C client 3.3.4 > 2013-12-03 02:44:53,191:22860(0x2b4d39022700):ZOO_INFO@log_env@662: > Client environment:host.name=vesta.apache.org > 2013-12-03 02:44:53,191:22860(0x2b4d39022700):ZOO_INFO@log_env@669: > Client environment:os.name=Linux > 2013-12-03 02:44:53,191:22860(0x2b4d39022700):ZOO_INFO@log_env@670: > Client environment:os.arch=3.2.0-51-generic > 2013-12-03 02:44:53,191:22860(0x2b4d39022700):ZOO_INFO@log_env@671: > Client environment:os.version=#77-Ubuntu SMP Wed Jul 24 20:18:19 UTC 2013 > 2013-12-03 02:44:53,191:22860(0x2b4d39625700):ZOO_INFO@log_env@658: > Client environment:zookeeper.version=zookeeper C client 3.3.4 > 2013-12-03 02:44:53,191:22860(0x2b4d39625700):ZOO_INFO@log_env@662: > Client environment:host.name=vesta.apache.org > 2013-12-03 02:44:53,191:22860(0x2b4d39625700):ZOO_INFO@log_env@669: > Client environment:os.name=Linux > 2013-12-03 02:44:53,191:22860(0x2b4d39625700):ZOO_INFO@log_env@670: > Client environment:os.arch=3.2.0-51-generic > 2013-12-03 02:44:53,191:22860(0x2b4d39625700):ZOO_INFO@log_env@671: > Client environment:os.version=#77-Ubuntu SMP Wed Jul 24 20:18:19 UTC 2013 > I1203 02:44:53.191808 22880 hierarchical_allocator_process.hpp:302] > Initializing hierarchical allocator process with master : > [email protected]:43939 > 2013-12-03 02:44:53,191:22860(0x2b4d39022700):ZOO_INFO@log_env@679: > Client environment:user.name=(null) > 2013-12-03 02:44:53,192:22860(0x2b4d39625700):ZOO_INFO@log_env@679: > Client environment:user.name=(null) > 2013-12-03 02:44:53,192:22860(0x2b4d39022700):ZOO_INFO@log_env@687: > Client environment:user.home=/home/jenkins > 2013-12-03 02:44:53,192:22860(0x2b4d39022700):ZOO_INFO@log_env@699: > Client > environment:user.dir=/home/hudson/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/src > 2013-12-03 02:44:53,192:22860(0x2b4d39625700):ZOO_INFO@log_env@687: > Client environment:user.home=/home/jenkins > 2013-12-03 02:44:53,192:22860(0x2b4d39022700):ZOO_INFO@zookeeper_init@727: > Initiating client connection, host=127.0.0.1:52432 sessionTimeout=10000 > watcher=0x2b4d366d7bd0 sessionId=0 sessionPasswd=<null> > context=0x2b4d4c17ec40 flags=0 > 2013-12-03 02:44:53,192:22860(0x2b4d39625700):ZOO_INFO@log_env@699: > Client > environment:user.dir=/home/hudson/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/src > 2013-12-03 02:44:53,192:22860(0x2b4d39625700):ZOO_INFO@zookeeper_init@727: > Initiating client connection, host=127.0.0.1:52432 sessionTimeout=10000 > watcher=0x2b4d366d7bd0 sessionId=0 sessionPasswd=<null> > context=0x2b4d6c202800 flags=0 > I1203 02:44:53.192318 22886 contender.cpp:122] Joining the ZK group with > data: '[email protected]:43939' > 2013-12-03 02:44:53,192:22860(0x2b4e90200700):ZOO_INFO@check_events@1585: > initiated connection to server [127.0.0.1:52432] > 2013-12-03 02:44:53,192:22860(0x2b4e50971700):ZOO_INFO@check_events@1585: > initiated connection to server [127.0.0.1:52432] > 2013-12-03 02:44:53,216:22860(0x2b4e90200700):ZOO_INFO@check_events@1632: > session establishment complete on server [127.0.0.1:52432], > sessionId=0x142b65803d5000a, negotiated timeout=10000 > 2013-12-03 02:44:53,217:22860(0x2b4e50971700):ZOO_INFO@check_events@1632: > session establishment complete on server [127.0.0.1:52432], > sessionId=0x142b65803d5000b, negotiated timeout=10000 > I1203 02:44:53.217350 22881 group.cpp:298] Trying to create path '/znode' > in ZooKeeper > I1203 02:44:53.217463 22885 group.cpp:298] Trying to create path '/znode' > in ZooKeeper > I1203 02:44:53.232877 22880 contender.cpp:203] New candidate (id='6', > data='[email protected]:43939') has entered the contest for leadership > I1203 02:44:53.233609 22882 detector.cpp:130] Detected a new leader > (id='6') > I1203 02:44:53.233616 22883 detector.cpp:130] Detected a new leader > (id='6') > I1203 02:44:53.233731 22886 detector.cpp:130] Detected a new leader > (id='6') > I1203 02:44:53.233748 22883 group.cpp:540] Trying to get > '/znode/0000000006' in ZooKeeper > I1203 02:44:53.233785 22882 group.cpp:540] Trying to get > '/znode/0000000006' in ZooKeeper > I1203 02:44:53.233918 22886 group.cpp:540] Trying to get > '/znode/0000000006' in ZooKeeper > I1203 02:44:53.234422 22883 detector.cpp:322] A new leading master (UPID= > [email protected]:43939) is detected > I1203 02:44:53.234505 22879 slave.cpp:497] New master detected at > [email protected]:43939 > I1203 02:44:53.234597 22879 slave.cpp:524] Detecting new master > I1203 02:44:53.234621 22883 status_update_manager.cpp:160] New master > detected at [email protected]:43939 > W1203 02:44:53.234721 22880 master.cpp:1378] Ignoring re-register slave > message from vesta.apache.org since not elected yet > I1203 02:44:53.234725 22882 detector.cpp:322] A new leading master (UPID= > [email protected]:43939) is detected > I1203 02:44:53.234767 22880 master.cpp:743] The newly elected leader is > [email protected]:43939 > I1203 02:44:53.234781 22880 master.cpp:747] Elected as the leading master! > I1203 02:44:53.234786 22882 detector.cpp:322] A new leading master (UPID= > [email protected]:43939) is detected > I1203 02:44:53.234863 22886 sched.cpp:207] New master detected at > [email protected]:43939 > I1203 02:44:53.234894 22886 sched.cpp:260] Authenticating with master > [email protected]:43939 > I1203 02:44:53.234959 22886 sched.cpp:229] Detecting new master > I1203 02:44:53.234977 22882 authenticatee.hpp:124] Creating new client > SASL connection > I1203 02:44:53.235108 22886 master.cpp:1839] Authenticating framework at > scheduler(131)@67.195.138.9:43939 > I1203 02:44:53.235198 22883 authenticator.hpp:140] Creating new server > SASL connection > I1203 02:44:53.235313 22882 authenticatee.hpp:212] Received SASL > authentication mechanisms: CRAM-MD5 > I1203 02:44:53.235348 22882 authenticatee.hpp:238] Attempting to > authenticate with mechanism 'CRAM-MD5' > I1203 02:44:53.235381 22882 authenticator.hpp:243] Received SASL > authentication start > I1203 02:44:53.235436 22882 authenticator.hpp:325] Authentication requires > more steps > I1203 02:44:53.235479 22882 authenticatee.hpp:258] Received SASL > authentication step > I1203 02:44:53.235541 22882 authenticator.hpp:271] Received SASL > authentication step > I1203 02:44:53.235594 22882 auxprop.cpp:81] Request to lookup properties > for user: 'test-principal' realm: 'vesta.apache.org' server FQDN: ' > vesta.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false > SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false > I1203 02:44:53.235602 22882 auxprop.cpp:153] Looking up auxiliary property > '*userPassword' > I1203 02:44:53.235621 22882 auxprop.cpp:153] Looking up auxiliary property > '*cmusaslsecretCRAM-MD5' > I1203 02:44:53.235632 22882 auxprop.cpp:81] Request to lookup properties > for user: 'test-principal' realm: 'vesta.apache.org' server FQDN: ' > vesta.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false > SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true > I1203 02:44:53.235640 22882 auxprop.cpp:103] Skipping auxiliary property > '*userPassword' since SASL_AUXPROP_AUTHZID == true > I1203 02:44:53.235645 22882 auxprop.cpp:103] Skipping auxiliary property > '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true > I1203 02:44:53.235656 22882 authenticator.hpp:317] Authentication success > I1203 02:44:53.235752 22881 authenticatee.hpp:298] Authentication success > I1203 02:44:53.235756 22882 master.cpp:1879] Successfully authenticated > framework at scheduler(131)@67.195.138.9:43939 > I1203 02:44:53.235865 22881 sched.cpp:334] Successfully authenticated with > master [email protected]:43939 > 2013-12-03 > 02:44:53,607:22860(0x2b4e84401700):ZOO_ERROR@handle_socket_error_msg@1579: > Socket [127.0.0.1:46528] zk retcode=-4, errno=111(Connection refused): > server refused to accept the client > I1203 02:44:54.008247 22879 master.cpp:1452] Attempting to re-register > slave 201312030244-160088899-43939-22860-0 at slave(136)@ > 67.195.138.9:43939 (vesta.apache.org) > I1203 02:44:54.008285 22879 master.cpp:2618] Adding slave > 201312030244-160088899-43939-22860-0 at vesta.apache.org with cpus(*):2; > mem(*):1024; disk(*):1.38501e+06; ports(*):[31000-32000] > I1203 02:44:54.008374 22883 slave.cpp:592] Re-registered with master > [email protected]:43939 > I1203 02:44:54.008412 22879 master.hpp:404] Adding task 0 with resources > cpus(*):1; mem(*):500 on slave 201312030244-160088899-43939-22860-0 ( > vesta.apache.org) > W1203 02:44:54.008442 22879 master.cpp:2713] Possibly orphaned task 0 of > framework 201312030244-160088899-43939-22860-0000 running on slave > 201312030244-160088899-43939-22860-0 (vesta.apache.org) > I1203 02:44:54.008714 22883 hierarchical_allocator_process.hpp:445] Added > slave 201312030244-160088899-43939-22860-0 (vesta.apache.org) with > cpus(*):2; mem(*):1024; disk(*):1.38501e+06; ports(*):[31000-32000] (and > cpus(*):1; mem(*):524; disk(*):1.38501e+06; ports(*):[31000-32000] > available) > I1203 02:44:54.008776 22883 hierarchical_allocator_process.hpp:708] > Performed allocation for slave 201312030244-160088899-43939-22860-0 in > 13442ns > I1203 02:44:54.009117 22881 master.cpp:886] Re-registering framework > 201312030244-160088899-43939-22860-0000 at scheduler(131)@ > 67.195.138.9:43939 > I1203 02:44:54.009397 22882 sched.cpp:383] Framework registered with > 201312030244-160088899-43939-22860-0000 > I1203 02:44:54.009438 22882 sched.cpp:397] Scheduler::registered took > 16549ns > I1203 02:44:54.009467 22879 slave.cpp:1292] Updating framework > 201312030244-160088899-43939-22860-0000 pid to scheduler(131)@ > 67.195.138.9:43939 > I1203 02:44:54.009537 22882 hierarchical_allocator_process.hpp:332] Added > framework 201312030244-160088899-43939-22860-0000 > I1203 02:44:54.009614 22882 hierarchical_allocator_process.hpp:752] > Offering cpus(*):1; mem(*):524; disk(*):1.38501e+06; ports(*):[31000-32000] > on slave 201312030244-160088899-43939-22860-0 to framework > 201312030244-160088899-43939-22860-0000 > I1203 02:44:54.009742 22882 hierarchical_allocator_process.hpp:688] > Performed allocation for 1 slaves in 180399ns > I1203 02:44:54.009811 22879 master.hpp:432] Adding offer > 201312030244-160088899-43939-22860-0 with resources cpus(*):1; mem(*):524; > disk(*):1.38501e+06; ports(*):[31000-32000] on slave > 201312030244-160088899-43939-22860-0 (vesta.apache.org) > I1203 02:44:54.009871 22879 master.cpp:1800] Sending 1 offers to framework > 201312030244-160088899-43939-22860-0000 > I1203 02:44:54.010038 22886 sched.cpp:517] Scheduler::resourceOffers took > 26338ns > I1203 02:44:54.010313 22883 sched.cpp:719] Stopping framework > '201312030244-160088899-43939-22860-0000' > I1203 02:44:54.010324 22860 master.cpp:553] Master terminating > I1203 02:44:54.010408 22860 master.cpp:209] Shutting down master > I1203 02:44:54.010419 22884 slave.cpp:1945] [email protected]:43939exited > W1203 02:44:54.010445 22884 slave.cpp:1948] Master disconnected! Waiting > for a new master to be elected > I1203 02:44:54.010479 22860 master.hpp:422] Removing task 0 with resources > cpus(*):1; mem(*):500 on slave 201312030244-160088899-43939-22860-0 ( > vesta.apache.org) > I1203 02:44:54.010581 22860 master.hpp:442] Removing offer > 201312030244-160088899-43939-22860-0 with resources cpus(*):1; mem(*):524; > disk(*):1.38501e+06; ports(*):[31000-32000] on slave > 201312030244-160088899-43939-22860-0 (vesta.apache.org) > I1203 02:44:54.010735 22879 hierarchical_allocator_process.hpp:637] > Recovered cpus(*):1; mem(*):500 (total allocatable: cpus(*):1; mem(*):500) > on slave 201312030244-160088899-43939-22860-0 from framework > 201312030244-160088899-43939-22860-0000 > I1203 02:44:54.010741 22860 master.cpp:252] Removing slave > 201312030244-160088899-43939-22860-0 (vesta.apache.org) > I1203 02:44:54.011318 22883 contender.cpp:172] Now cancelling the > membership: 6 > I1203 02:44:54.011404 22884 group.cpp:496] Trying to remove > '/znode/0000000006' in ZooKeeper > I1203 02:44:54.020333 22886 monitor.cpp:193] Publishing resource usage for > executor 'default' of framework '201312030244-160088899-43939-22860-0000' > 2013-12-03 02:44:54,021:22860(0x2b4d38e1d7c0):ZOO_INFO@zookeeper_close@2304: > Closing zookeeper sessionId=0x142b65803d5000a to [127.0.0.1:52432] > > 2013-12-03 02:44:54,022:22860(0x2b4d38e1d7c0):ZOO_INFO@zookeeper_close@2304: > Closing zookeeper sessionId=0x142b65803d5000b to [127.0.0.1:52432] > > I1203 02:44:54.022768 22879 detector.cpp:116] The current leader (id=6) is > lost > I1203 02:44:54.022826 22879 detector.cpp:138] No new leader is elected > after election > I1203 02:44:54.022838 22882 detector.cpp:116] The current leader (id=6) is > lost > I1203 02:44:54.022989 22882 detector.cpp:138] No new leader is elected > after election > I1203 02:44:54.023125 22883 slave.cpp:391] Slave terminating > I1203 02:44:54.023167 22883 slave.cpp:1122] Asked to shut down framework > 201312030244-160088899-43939-22860-0000 by @0.0.0.0:0 > I1203 02:44:54.023186 22883 slave.cpp:1147] Shutting down framework > 201312030244-160088899-43939-22860-0000 > I1203 02:44:54.023203 22883 slave.cpp:2411] Shutting down executor > 'default' of framework 201312030244-160088899-43939-22860-0000 > I1203 02:44:54.023252 22884 exec.cpp:375] Executor asked to shutdown > I1203 02:44:54.023290 22884 exec.cpp:390] Executor::shutdown took 15884ns > 2013-12-03 02:44:54,023:22860(0x2b4d38e1d7c0):ZOO_INFO@zookeeper_close@2304: > Closing zookeeper sessionId=0x142b65803d50009 to [127.0.0.1:52432] > > 2013-12-03 02:44:54,024:22860(0x2b4d38e1d7c0):ZOO_INFO@zookeeper_close@2304: > Closing zookeeper sessionId=0x142b65803d50008 to [127.0.0.1:52432] > > [ OK ] AllocatorZooKeeperTest/0.SlaveReregistersFirst (1053 ms) > I1203 02:44:54.027425 22860 zookeeper_test_server.cpp:93] Shutdown > ZooKeeperTestServer on port 52432 > [----------] 2 tests from AllocatorZooKeeperTest/0 (3250 ms total) > > [----------] Global test environment tear-down > [==========] 245 tests from 43 test cases ran. (135875 ms total) > [ PASSED ] 244 tests. > [ FAILED ] 1 test, listed below: > [ FAILED ] FaultToleranceTest.ReregisterFrameworkExitedExecutor > > 1 FAILED TEST > YOU HAVE 2 DISABLED TESTS > > make[3]: *** [check-local] Error 1 > make[3]: Leaving directory > `/home/hudson/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/src' > make[2]: *** [check-am] Error 2 > make[2]: Leaving directory > `/home/hudson/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/src' > make[1]: *** [check] Error 2 > make[1]: Leaving directory > `/home/hudson/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/src' > make: *** [check-recursive] Error 1 > Build step 'Execute shell' marked build as failure >
