See <https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Set-JAVA_HOME/1779/>
------------------------------------------ [...truncated 22367 lines...] I1128 21:58:46.517117 13832 group.cpp:297] Trying to create path '/znode' in ZooKeeper 2013-11-28 21:58:46,517:13810(0x2b0b2551a700):ZOO_INFO@check_events@1632: session establishment complete on server [127.0.0.1:55000], sessionId=0x142a0b8a70a0009, negotiated timeout=10000 I1128 21:58:46.517601 13837 group.cpp:297] Trying to create path '/znode' in ZooKeeper I1128 21:58:46.531468 13834 contender.cpp:203] New candidate (id='4', data='[email protected]:44735') has entered the contest for leadership I1128 21:58:46.532529 13835 detector.cpp:130] Detected a new leader (id='4') I1128 21:58:46.532626 13835 group.cpp:539] Trying to get '/znode/0000000004' in ZooKeeper I1128 21:58:46.532634 13833 detector.cpp:130] Detected a new leader (id='4') I1128 21:58:46.532706 13833 group.cpp:539] Trying to get '/znode/0000000004' in ZooKeeper I1128 21:58:46.532891 13837 detector.cpp:130] Detected a new leader (id='4') I1128 21:58:46.532980 13834 group.cpp:539] Trying to get '/znode/0000000004' in ZooKeeper I1128 21:58:46.533495 13833 detector.cpp:322] A new leading master ([email protected]:44735) is detected I1128 21:58:46.533532 13833 slave.cpp:497] New master detected at [email protected]:44735 I1128 21:58:46.533584 13833 slave.cpp:524] Detecting new master I1128 21:58:46.533622 13833 status_update_manager.cpp:160] New master detected at [email protected]:44735 W1128 21:58:46.533654 13833 master.cpp:1333] Ignoring register slave message from janus.apache.org since not elected yet I1128 21:58:46.533711 13835 detector.cpp:322] A new leading master ([email protected]:44735) is detected I1128 21:58:46.533762 13839 master.cpp:744] The newly elected leader is [email protected]:44735 I1128 21:58:46.533776 13839 master.cpp:748] Elected as the leading master! I1128 21:58:46.533856 13834 detector.cpp:322] A new leading master ([email protected]:44735) is detected I1128 21:58:46.533895 13834 sched.cpp:207] New master detected at [email protected]:44735 I1128 21:58:46.533908 13834 sched.cpp:260] Authenticating with master [email protected]:44735 I1128 21:58:46.533959 13834 sched.cpp:229] Detecting new master I1128 21:58:46.533999 13834 authenticatee.hpp:124] Creating new client SASL connection I1128 21:58:46.534127 13834 master.cpp:1840] Authenticating framework at scheduler(131)@67.195.138.60:44735 I1128 21:58:46.534201 13834 authenticator.hpp:140] Creating new server SASL connection I1128 21:58:46.534286 13834 authenticatee.hpp:212] Received SASL authentication mechanisms: CRAM-MD5 I1128 21:58:46.534301 13834 authenticatee.hpp:238] Attempting to authenticate with mechanism 'CRAM-MD5' I1128 21:58:46.534319 13834 authenticator.hpp:243] Received SASL authentication start I1128 21:58:46.534373 13834 authenticator.hpp:325] Authentication requires more steps I1128 21:58:46.534389 13834 authenticatee.hpp:258] Received SASL authentication step I1128 21:58:46.534417 13834 authenticator.hpp:271] Received SASL authentication step I1128 21:58:46.534433 13834 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'janus.apache.org' server FQDN: 'janus.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I1128 21:58:46.534442 13834 auxprop.cpp:153] Looking up auxiliary property '*userPassword' I1128 21:58:46.534457 13834 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I1128 21:58:46.534468 13834 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'janus.apache.org' server FQDN: 'janus.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I1128 21:58:46.534476 13834 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I1128 21:58:46.534482 13834 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I1128 21:58:46.534493 13834 authenticator.hpp:317] Authentication success I1128 21:58:46.534512 13834 authenticatee.hpp:298] Authentication success I1128 21:58:46.534526 13834 master.cpp:1880] Successfully authenticated framework at scheduler(131)@67.195.138.60:44735 I1128 21:58:46.534576 13834 sched.cpp:334] Successfully authenticated with master [email protected]:44735 I1128 21:58:46.534610 13834 master.cpp:799] Received registration request from scheduler(131)@67.195.138.60:44735 I1128 21:58:46.534690 13834 master.cpp:817] Registering framework 201311282158-1015726915-44735-13810-0000 at scheduler(131)@67.195.138.60:44735 I1128 21:58:46.534734 13834 sched.cpp:383] Framework registered with 201311282158-1015726915-44735-13810-0000 I1128 21:58:46.534754 13834 sched.cpp:397] Scheduler::registered took 11747ns I1128 21:58:46.534776 13834 hierarchical_allocator_process.hpp:332] Added framework 201311282158-1015726915-44735-13810-0000 I1128 21:58:46.534785 13834 hierarchical_allocator_process.hpp:726] No resources available to allocate! I1128 21:58:46.534790 13834 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 6701ns I1128 21:58:47.471740 13838 hierarchical_allocator_process.hpp:726] No resources available to allocate! I1128 21:58:47.471756 13838 hierarchical_allocator_process.hpp:688] Performed allocation for 0 slaves in 27368ns I1128 21:58:47.533915 13838 master.cpp:1364] Attempting to register slave on janus.apache.org at slave(136)@67.195.138.60:44735 I1128 21:58:47.533929 13838 master.cpp:2619] Adding slave 201311282158-1015726915-44735-13810-0 at janus.apache.org with cpus(*):2; mem(*):1024; disk(*):23038; ports(*):[31000-32000] I1128 21:58:47.534041 13838 slave.cpp:542] Registered with master [email protected]:44735; given slave ID 201311282158-1015726915-44735-13810-0 I1128 21:58:47.534104 13838 hierarchical_allocator_process.hpp:445] Added slave 201311282158-1015726915-44735-13810-0 (janus.apache.org) with cpus(*):2; mem(*):1024; disk(*):23038; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):23038; ports(*):[31000-32000] available) I1128 21:58:47.534164 13838 hierarchical_allocator_process.hpp:752] Offering cpus(*):2; mem(*):1024; disk(*):23038; ports(*):[31000-32000] on slave 201311282158-1015726915-44735-13810-0 to framework 201311282158-1015726915-44735-13810-0000 I1128 21:58:47.534288 13838 hierarchical_allocator_process.hpp:708] Performed allocation for slave 201311282158-1015726915-44735-13810-0 in 153182ns I1128 21:58:47.534344 13838 master.hpp:432] Adding offer 201311282158-1015726915-44735-13810-0 with resources cpus(*):2; mem(*):1024; disk(*):23038; ports(*):[31000-32000] on slave 201311282158-1015726915-44735-13810-0 (janus.apache.org) I1128 21:58:47.534390 13838 master.cpp:1801] Sending 1 offers to framework 201311282158-1015726915-44735-13810-0000 I1128 21:58:47.534646 13838 sched.cpp:517] Scheduler::resourceOffers took 181993ns I1128 21:58:47.534728 13838 master.cpp:2132] Processing reply for offer 201311282158-1015726915-44735-13810-0 on slave 201311282158-1015726915-44735-13810-0 (janus.apache.org) for framework 201311282158-1015726915-44735-13810-0000 I1128 21:58:47.534813 13838 master.hpp:404] Adding task 0 with resources cpus(*):1; mem(*):500 on slave 201311282158-1015726915-44735-13810-0 (janus.apache.org) I1128 21:58:47.534842 13838 master.cpp:2256] Launching task 0 of framework 201311282158-1015726915-44735-13810-0000 with resources cpus(*):1; mem(*):500 on slave 201311282158-1015726915-44735-13810-0 (janus.apache.org) I1128 21:58:47.534968 13838 master.hpp:442] Removing offer 201311282158-1015726915-44735-13810-0 with resources cpus(*):2; mem(*):1024; disk(*):23038; ports(*):[31000-32000] on slave 201311282158-1015726915-44735-13810-0 (janus.apache.org) I1128 21:58:47.535037 13838 slave.cpp:722] Got assigned task 0 for framework 201311282158-1015726915-44735-13810-0000 I1128 21:58:47.535190 13838 slave.cpp:833] Launching task 0 for framework 201311282158-1015726915-44735-13810-0000 I1128 21:58:47.535619 13833 hierarchical_allocator_process.hpp:547] Framework 201311282158-1015726915-44735-13810-0000 left cpus(*):1; mem(*):524; disk(*):23038; ports(*):[31000-32000] unused on slave 201311282158-1015726915-44735-13810-0 I1128 21:58:47.535717 13833 hierarchical_allocator_process.hpp:590] Framework 201311282158-1015726915-44735-13810-0000 filtered slave 201311282158-1015726915-44735-13810-0 for 5secs I1128 21:58:47.537159 13838 slave.cpp:943] Queuing task '0' for executor default of framework '201311282158-1015726915-44735-13810-0000 I1128 21:58:47.537240 13832 slave.cpp:466] Successfully attached file '/tmp/AllocatorZooKeeperTest_0_SlaveReregistersFirst_Dw000D/slaves/201311282158-1015726915-44735-13810-0/frameworks/201311282158-1015726915-44735-13810-0000/executors/default/runs/50f7b4de-e9d3-4975-8998-34169f2e7a04' I1128 21:58:47.538936 13834 exec.cpp:178] Executor started at: executor(45)@67.195.138.60:44735 with pid 13810 I1128 21:58:47.538969 13836 slave.cpp:2078] Monitoring executor default of framework 201311282158-1015726915-44735-13810-0000 forked at pid 13810 I1128 21:58:47.539054 13836 slave.cpp:1411] Got registration for executor 'default' of framework 201311282158-1015726915-44735-13810-0000 I1128 21:58:47.539264 13836 slave.cpp:1532] Flushing queued task 0 for executor 'default' of framework 201311282158-1015726915-44735-13810-0000 I1128 21:58:47.539295 13838 exec.cpp:202] Executor registered on slave 201311282158-1015726915-44735-13810-0 I1128 21:58:47.540875 13838 exec.cpp:214] Executor::registered took 13821ns I1128 21:58:47.540933 13838 exec.cpp:289] Executor asked to run task '0' I1128 21:58:47.540971 13838 exec.cpp:298] Executor::launchTask took 24311ns I1128 21:58:47.542496 13838 exec.cpp:521] Executor sending status update TASK_RUNNING (UUID: f13f0aa9-23e9-4e1f-89f8-67df72ac2051) for task 0 of framework 201311282158-1015726915-44735-13810-0000 I1128 21:58:47.542573 13838 slave.cpp:1745] Handling status update TASK_RUNNING (UUID: f13f0aa9-23e9-4e1f-89f8-67df72ac2051) for task 0 of framework 201311282158-1015726915-44735-13810-0000 from executor(45)@67.195.138.60:44735 I1128 21:58:47.542665 13833 status_update_manager.cpp:312] Received status update TASK_RUNNING (UUID: f13f0aa9-23e9-4e1f-89f8-67df72ac2051) for task 0 of framework 201311282158-1015726915-44735-13810-0000 I1128 21:58:47.542687 13833 status_update_manager.cpp:491] Creating StatusUpdate stream for task 0 of framework 201311282158-1015726915-44735-13810-0000 I1128 21:58:47.542763 13833 status_update_manager.cpp:365] Forwarding status update TASK_RUNNING (UUID: f13f0aa9-23e9-4e1f-89f8-67df72ac2051) for task 0 of framework 201311282158-1015726915-44735-13810-0000 to [email protected]:44735 I1128 21:58:47.542887 13838 master.cpp:1550] Status update TASK_RUNNING (UUID: f13f0aa9-23e9-4e1f-89f8-67df72ac2051) for task 0 of framework 201311282158-1015726915-44735-13810-0000 from slave(136)@67.195.138.60:44735 I1128 21:58:47.542897 13837 slave.cpp:1864] Status update manager successfully handled status update TASK_RUNNING (UUID: f13f0aa9-23e9-4e1f-89f8-67df72ac2051) for task 0 of framework 201311282158-1015726915-44735-13810-0000 I1128 21:58:47.542915 13837 slave.cpp:1870] Sending acknowledgement for status update TASK_RUNNING (UUID: f13f0aa9-23e9-4e1f-89f8-67df72ac2051) for task 0 of framework 201311282158-1015726915-44735-13810-0000 to executor(45)@67.195.138.60:44735 I1128 21:58:47.542976 13833 exec.cpp:335] Executor received status update acknowledgement f13f0aa9-23e9-4e1f-89f8-67df72ac2051 for task 0 of framework 201311282158-1015726915-44735-13810-0000 I1128 21:58:47.542986 13835 sched.cpp:608] Scheduler::statusUpdate took 44940ns I1128 21:58:47.543128 13835 status_update_manager.cpp:390] Received status update acknowledgement (UUID: f13f0aa9-23e9-4e1f-89f8-67df72ac2051) for task 0 of framework 201311282158-1015726915-44735-13810-0000 I1128 21:58:47.543203 13835 slave.cpp:1351] Status update manager successfully handled status update acknowledgement (UUID: f13f0aa9-23e9-4e1f-89f8-67df72ac2051) for task 0 of framework 201311282158-1015726915-44735-13810-0000 I1128 21:58:47.543233 13810 master.cpp:554] Master terminating I1128 21:58:47.543265 13810 master.cpp:210] Shutting down master I1128 21:58:47.543287 13833 slave.cpp:1945] [email protected]:44735 exited W1128 21:58:47.543300 13833 slave.cpp:1948] Master disconnected! Waiting for a new master to be elected I1128 21:58:47.543313 13810 master.hpp:422] Removing task 0 with resources cpus(*):1; mem(*):500 on slave 201311282158-1015726915-44735-13810-0 (janus.apache.org) I1128 21:58:47.543408 13810 master.cpp:253] Removing slave 201311282158-1015726915-44735-13810-0 (janus.apache.org) I1128 21:58:47.543463 13832 hierarchical_allocator_process.hpp:637] Recovered cpus(*):1; mem(*):500 (total allocatable: cpus(*):2; mem(*):1024; disk(*):23038; ports(*):[31000-32000]) on slave 201311282158-1015726915-44735-13810-0 from framework 201311282158-1015726915-44735-13810-0000 I1128 21:58:47.543792 13810 contender.cpp:172] Now cancelling the membership: 4 I1128 21:58:47.543853 13835 group.cpp:495] Trying to remove '/znode/0000000004' in ZooKeeper 2013-11-28 21:58:47,598:13810(0x2b0996c867c0):ZOO_INFO@zookeeper_close@2304: Closing zookeeper sessionId=0x142a0b8a70a0006 to [127.0.0.1:55000] I1128 21:58:47.598280 13833 detector.cpp:116] The current leader (id=4) is lost I1128 21:58:47.598296 13833 detector.cpp:138] No new leader is elected after election I1128 21:58:47.598436 13832 sched.cpp:201] Scheduler::disconnected took 10179ns I1128 21:58:47.598507 13832 sched.cpp:223] No master detected I1128 21:58:47.598515 13832 sched.cpp:229] Detecting new master I1128 21:58:47.598625 13837 detector.cpp:116] The current leader (id=4) is lost I1128 21:58:47.598654 13837 detector.cpp:138] No new leader is elected after election I1128 21:58:47.598762 13838 slave.cpp:518] Lost leading master I1128 21:58:47.598775 13838 slave.cpp:524] Detecting new master 2013-11-28 21:58:47,599:13810(0x2b0996c867c0):ZOO_INFO@zookeeper_close@2304: Closing zookeeper sessionId=0x142a0b8a70a0007 to [127.0.0.1:55000] I1128 21:58:47.600005 13832 master.cpp:285] Master started on 67.195.138.60:44735 I1128 21:58:47.600039 13832 master.cpp:299] Master ID: 201311282158-1015726915-44735-13810 I1128 21:58:47.600047 13832 master.cpp:302] Master only allowing authenticated frameworks to register! 2013-11-28 21:58:47,600:13810(0x2b0997a91700):ZOO_INFO@log_env@658: Client environment:zookeeper.version=zookeeper C client 3.3.4 2013-11-28 21:58:47,600:13810(0x2b0997a91700):ZOO_INFO@log_env@662: Client environment:host.name=janus 2013-11-28 21:58:47,600:13810(0x2b0997a91700):ZOO_INFO@log_env@669: Client environment:os.name=Linux 2013-11-28 21:58:47,600:13810(0x2b0997a91700):ZOO_INFO@log_env@670: Client environment:os.arch=3.2.0-51-generic 2013-11-28 21:58:47,600:13810(0x2b0997a91700):ZOO_INFO@log_env@671: Client environment:os.version=#77-Ubuntu SMP Wed Jul 24 20:18:19 UTC 2013 I1128 21:58:47.600392 13834 master.cpp:85] No whitelist given. Advertising offers for all slaves 2013-11-28 21:58:47,600:13810(0x2b0997c92700):ZOO_INFO@log_env@658: Client environment:zookeeper.version=zookeeper C client 3.3.4 2013-11-28 21:58:47,600:13810(0x2b0997c92700):ZOO_INFO@log_env@662: Client environment:host.name=janus 2013-11-28 21:58:47,600:13810(0x2b0997c92700):ZOO_INFO@log_env@669: Client environment:os.name=Linux 2013-11-28 21:58:47,600:13810(0x2b0997c92700):ZOO_INFO@log_env@670: Client environment:os.arch=3.2.0-51-generic 2013-11-28 21:58:47,600:13810(0x2b0997c92700):ZOO_INFO@log_env@671: Client environment:os.version=#77-Ubuntu SMP Wed Jul 24 20:18:19 UTC 2013 2013-11-28 21:58:47,600:13810(0x2b0997a91700):ZOO_INFO@log_env@679: Client environment:user.name=(null) I1128 21:58:47.600615 13834 hierarchical_allocator_process.hpp:302] Initializing hierarchical allocator process with master : [email protected]:44735 2013-11-28 21:58:47,600:13810(0x2b0997a91700):ZOO_INFO@log_env@687: Client environment:user.home=/home/jenkins I1128 21:58:47.600749 13837 contender.cpp:122] Joining the ZK group with data: '[email protected]:44735' 2013-11-28 21:58:47,600:13810(0x2b0997a91700):ZOO_INFO@log_env@699: Client environment:user.dir=<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Set-JAVA_HOME/ws/build/src> 2013-11-28 21:58:47,600:13810(0x2b0997a91700):ZOO_INFO@zookeeper_init@727: Initiating client connection, host=127.0.0.1:55000 sessionTimeout=10000 watcher=0x2b0994545050 sessionId=0 sessionPasswd=<null> context=0x2b09b00287b0 flags=0 2013-11-28 21:58:47,600:13810(0x2b0997c92700):ZOO_INFO@log_env@679: Client environment:user.name=(null) 2013-11-28 21:58:47,600:13810(0x2b0997c92700):ZOO_INFO@log_env@687: Client environment:user.home=/home/jenkins 2013-11-28 21:58:47,600:13810(0x2b0997c92700):ZOO_INFO@log_env@699: Client environment:user.dir=<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Set-JAVA_HOME/ws/build/src> 2013-11-28 21:58:47,600:13810(0x2b0997c92700):ZOO_INFO@zookeeper_init@727: Initiating client connection, host=127.0.0.1:55000 sessionTimeout=10000 watcher=0x2b0994545050 sessionId=0 sessionPasswd=<null> context=0x2b09bc033d70 flags=0 2013-11-28 21:58:47,601:13810(0x2b0b58401700):ZOO_INFO@check_events@1585: initiated connection to server [127.0.0.1:55000] 2013-11-28 21:58:47,601:13810(0x2b0b64200700):ZOO_INFO@check_events@1585: initiated connection to server [127.0.0.1:55000] 2013-11-28 21:58:47,639:13810(0x2b0b58401700):ZOO_INFO@check_events@1632: session establishment complete on server [127.0.0.1:55000], sessionId=0x142a0b8a70a000a, negotiated timeout=10000 2013-11-28 21:58:47,640:13810(0x2b0b64200700):ZOO_INFO@check_events@1632: session establishment complete on server [127.0.0.1:55000], sessionId=0x142a0b8a70a000b, negotiated timeout=10000 I1128 21:58:47.640877 13834 group.cpp:297] Trying to create path '/znode' in ZooKeeper I1128 21:58:47.641053 13832 group.cpp:297] Trying to create path '/znode' in ZooKeeper I1128 21:58:47.665093 13835 contender.cpp:203] New candidate (id='6', data='[email protected]:44735') has entered the contest for leadership I1128 21:58:47.676384 13839 detector.cpp:130] Detected a new leader (id='6') I1128 21:58:47.676429 13837 detector.cpp:130] Detected a new leader (id='6') I1128 21:58:47.676480 13838 detector.cpp:130] Detected a new leader (id='6') I1128 21:58:47.676594 13837 group.cpp:539] Trying to get '/znode/0000000006' in ZooKeeper I1128 21:58:47.676676 13832 group.cpp:539] Trying to get '/znode/0000000006' in ZooKeeper I1128 21:58:47.676751 13838 group.cpp:539] Trying to get '/znode/0000000006' in ZooKeeper I1128 21:58:47.677417 13838 detector.cpp:322] A new leading master ([email protected]:44735) is detected I1128 21:58:47.677464 13835 sched.cpp:207] New master detected at [email protected]:44735 I1128 21:58:47.677479 13835 sched.cpp:260] Authenticating with master [email protected]:44735 I1128 21:58:47.677536 13835 sched.cpp:229] Detecting new master I1128 21:58:47.677558 13838 authenticatee.hpp:124] Creating new client SASL connection I1128 21:58:47.677631 13839 detector.cpp:322] A new leading master ([email protected]:44735) is detected I1128 21:58:47.677635 13835 detector.cpp:322] A new leading master ([email protected]:44735) is detected I1128 21:58:47.677736 13838 slave.cpp:497] New master detected at [email protected]:44735 I1128 21:58:47.677747 13837 master.cpp:1840] Authenticating framework at scheduler(131)@67.195.138.60:44735 I1128 21:58:47.677794 13839 status_update_manager.cpp:160] New master detected at [email protected]:44735 I1128 21:58:47.677837 13836 authenticator.hpp:140] Creating new server SASL connection I1128 21:58:47.677847 13837 master.cpp:744] The newly elected leader is [email protected]:44735 I1128 21:58:47.677862 13837 master.cpp:748] Elected as the leading master! I1128 21:58:47.677861 13838 slave.cpp:524] Detecting new master I1128 21:58:47.677997 13839 authenticatee.hpp:212] Received SASL authentication mechanisms: CRAM-MD5 I1128 21:58:47.678014 13839 authenticatee.hpp:238] Attempting to authenticate with mechanism 'CRAM-MD5' I1128 21:58:47.678027 13837 master.cpp:1453] Attempting to re-register slave 201311282158-1015726915-44735-13810-0 at slave(136)@67.195.138.60:44735 (janus.apache.org) I1128 21:58:47.678050 13839 authenticator.hpp:243] Received SASL authentication start I1128 21:58:47.678043 13837 master.cpp:2619] Adding slave 201311282158-1015726915-44735-13810-0 at janus.apache.org with cpus(*):2; mem(*):1024; disk(*):23038; ports(*):[31000-32000] I1128 21:58:47.678114 13839 authenticator.hpp:325] Authentication requires more steps I1128 21:58:47.678120 13836 slave.cpp:592] Re-registered with master [email protected]:44735 I1128 21:58:47.678143 13837 master.hpp:404] Adding task 0 with resources cpus(*):1; mem(*):500 on slave 201311282158-1015726915-44735-13810-0 (janus.apache.org) I1128 21:58:47.678167 13839 authenticatee.hpp:258] Received SASL authentication step W1128 21:58:47.678170 13837 master.cpp:2714] Possibly orphaned task 0 of framework 201311282158-1015726915-44735-13810-0000 running on slave 201311282158-1015726915-44735-13810-0 (janus.apache.org) I1128 21:58:47.678225 13839 authenticator.hpp:271] Received SASL authentication step I1128 21:58:47.678247 13839 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'janus.apache.org' server FQDN: 'janus.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I1128 21:58:47.678254 13839 auxprop.cpp:153] Looking up auxiliary property '*userPassword' I1128 21:58:47.678269 13839 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I1128 21:58:47.678280 13839 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'janus.apache.org' server FQDN: 'janus.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I1128 21:58:47.678287 13839 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I1128 21:58:47.678292 13839 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I1128 21:58:47.678302 13839 authenticator.hpp:317] Authentication success I1128 21:58:47.678357 13837 authenticatee.hpp:298] Authentication success I1128 21:58:47.678397 13832 master.cpp:1880] Successfully authenticated framework at scheduler(131)@67.195.138.60:44735 I1128 21:58:47.678465 13837 sched.cpp:334] Successfully authenticated with master [email protected]:44735 I1128 21:58:47.678449 13835 hierarchical_allocator_process.hpp:445] Added slave 201311282158-1015726915-44735-13810-0 (janus.apache.org) with cpus(*):2; mem(*):1024; disk(*):23038; ports(*):[31000-32000] (and cpus(*):1; mem(*):524; disk(*):23038; ports(*):[31000-32000] available) I1128 21:58:47.678503 13835 hierarchical_allocator_process.hpp:708] Performed allocation for slave 201311282158-1015726915-44735-13810-0 in 8591ns I1128 21:58:48.540316 13837 monitor.cpp:193] Publishing resource usage for executor 'default' of framework '201311282158-1015726915-44735-13810-0000' 2013-11-28 21:58:48,564:13810(0x2b0b64401700):ZOO_ERROR@handle_socket_error_msg@1579: Socket [127.0.0.1:50613] zk retcode=-4, errno=111(Connection refused): server refused to accept the client I1128 21:58:48.601323 13839 hierarchical_allocator_process.hpp:688] Performed allocation for 1 slaves in 15734ns I1128 21:58:48.679594 13837 master.cpp:887] Re-registering framework 201311282158-1015726915-44735-13810-0000 at scheduler(131)@67.195.138.60:44735 I1128 21:58:48.679883 13835 slave.cpp:1292] Updating framework 201311282158-1015726915-44735-13810-0000 pid to scheduler(131)@67.195.138.60:44735 I1128 21:58:48.679963 13838 sched.cpp:383] Framework registered with 201311282158-1015726915-44735-13810-0000 I1128 21:58:48.679965 13836 hierarchical_allocator_process.hpp:332] Added framework 201311282158-1015726915-44735-13810-0000 I1128 21:58:48.679993 13838 sched.cpp:397] Scheduler::registered took 10857ns I1128 21:58:48.680037 13836 hierarchical_allocator_process.hpp:752] Offering cpus(*):1; mem(*):524; disk(*):23038; ports(*):[31000-32000] on slave 201311282158-1015726915-44735-13810-0 to framework 201311282158-1015726915-44735-13810-0000 I1128 21:58:48.680181 13836 hierarchical_allocator_process.hpp:688] Performed allocation for 1 slaves in 183810ns I1128 21:58:48.680263 13835 master.hpp:432] Adding offer 201311282158-1015726915-44735-13810-0 with resources cpus(*):1; mem(*):524; disk(*):23038; ports(*):[31000-32000] on slave 201311282158-1015726915-44735-13810-0 (janus.apache.org) I1128 21:58:48.680328 13835 master.cpp:1801] Sending 1 offers to framework 201311282158-1015726915-44735-13810-0000 I1128 21:58:48.680491 13832 sched.cpp:517] Scheduler::resourceOffers took 35186ns I1128 21:58:48.680696 13832 sched.cpp:719] Stopping framework '201311282158-1015726915-44735-13810-0000' I1128 21:58:48.680711 13835 master.cpp:554] Master terminating I1128 21:58:48.680742 13835 slave.cpp:1945] [email protected]:44735 exited W1128 21:58:48.680754 13835 slave.cpp:1948] Master disconnected! Waiting for a new master to be elected I1128 21:58:48.680762 13810 master.cpp:210] Shutting down master I1128 21:58:48.680814 13810 master.hpp:422] Removing task 0 with resources cpus(*):1; mem(*):500 on slave 201311282158-1015726915-44735-13810-0 (janus.apache.org) I1128 21:58:48.680899 13810 master.hpp:442] Removing offer 201311282158-1015726915-44735-13810-0 with resources cpus(*):1; mem(*):524; disk(*):23038; ports(*):[31000-32000] on slave 201311282158-1015726915-44735-13810-0 (janus.apache.org) I1128 21:58:48.681028 13810 master.cpp:253] Removing slave 201311282158-1015726915-44735-13810-0 (janus.apache.org) I1128 21:58:48.681129 13837 hierarchical_allocator_process.hpp:637] Recovered cpus(*):1; mem(*):500 (total allocatable: cpus(*):1; mem(*):500) on slave 201311282158-1015726915-44735-13810-0 from framework 201311282158-1015726915-44735-13810-0000 I1128 21:58:48.681494 13810 contender.cpp:172] Now cancelling the membership: 6 I1128 21:58:48.681556 13836 group.cpp:495] Trying to remove '/znode/0000000006' in ZooKeeper 2013-11-28 21:58:48,747:13810(0x2b0996c867c0):ZOO_INFO@zookeeper_close@2304: Closing zookeeper sessionId=0x142a0b8a70a000a to [127.0.0.1:55000] I1128 21:58:48.748072 13835 detector.cpp:116] The current leader (id=6) is lost I1128 21:58:48.748088 13835 detector.cpp:138] No new leader is elected after election I1128 21:58:48.748332 13835 detector.cpp:116] The current leader (id=6) is lost I1128 21:58:48.748347 13835 detector.cpp:138] No new leader is elected after election I1128 21:58:48.748529 13833 slave.cpp:518] Lost leading master I1128 21:58:48.748553 13833 slave.cpp:524] Detecting new master 2013-11-28 21:58:48,748:13810(0x2b0996c867c0):ZOO_INFO@zookeeper_close@2304: Closing zookeeper sessionId=0x142a0b8a70a000b to [127.0.0.1:55000] I1128 21:58:48.748880 13810 slave.cpp:391] Slave terminating I1128 21:58:48.748905 13810 slave.cpp:1122] Asked to shut down framework 201311282158-1015726915-44735-13810-0000 by @0.0.0.0:0 W1128 21:58:48.748915 13810 slave.cpp:1130] Ignoring shutdown framework message for 201311282158-1015726915-44735-13810-0000 because the slave has not yet registered with the master I1128 21:58:48.748997 13837 exec.cpp:455] Slave exited ... shutting down I1128 21:58:48.749025 13837 exec.cpp:472] Executor::shutdown took 12317ns 2013-11-28 21:58:48,749:13810(0x2b0996c867c0):ZOO_INFO@zookeeper_close@2304: Closing zookeeper sessionId=0x142a0b8a70a0008 to [127.0.0.1:55000] 2013-11-28 21:58:48,749:13810(0x2b0996c867c0):ZOO_INFO@zookeeper_close@2304: Closing zookeeper sessionId=0x142a0b8a70a0009 to [127.0.0.1:55000] [ OK ] AllocatorZooKeeperTest/0.SlaveReregistersFirst (2281 ms) I1128 21:58:48.755717 13810 zookeeper_test_server.cpp:93] Shutdown ZooKeeperTestServer on port 55000 [----------] 2 tests from AllocatorZooKeeperTest/0 (3491 ms total) [----------] Global test environment tear-down [==========] 245 tests from 43 test cases ran. (150759 ms total) [ PASSED ] 244 tests. [ FAILED ] 1 test, listed below: [ FAILED ] FaultToleranceTest.SchedulerFailoverStatusUpdate 1 FAILED TEST YOU HAVE 2 DISABLED TESTS make[3]: *** [check-local] Error 1 make[3]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Set-JAVA_HOME/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-Set-JAVA_HOME/ws/build/src'> make[1]: *** [check] Error 2 make[1]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Set-JAVA_HOME/ws/build/src'> make: *** [check-recursive] Error 1 Build step 'Execute shell' marked build as failure
