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 ([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 ([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 ([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]:43939 exited 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 ([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 ([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 ([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]:43939 exited 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
