[
https://issues.apache.org/jira/browse/MESOS-1019?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Vinod Kone resolved MESOS-1019.
-------------------------------
Resolution: Duplicate
> AllocatorZooKeeperTest/0.SlaveReregistersFirst is flaky.
> --------------------------------------------------------
>
> Key: MESOS-1019
> URL: https://issues.apache.org/jira/browse/MESOS-1019
> Project: Mesos
> Issue Type: Bug
> Components: test
> Affects Versions: 0.18.0
> Reporter: Benjamin Mahler
> Fix For: 0.19.0
>
>
> This test failed on Jenkins:
> https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Set-JAVA_HOME/1902/consoleFull
> {noformat}
> [ RUN ] AllocatorZooKeeperTest/0.SlaveReregistersFirst
> I0219 17:03:05.874918 26618 master.cpp:240] Master ID:
> 2014-02-19-17:03:05-160088899-59606-26618 Hostname: vesta.apache.org
> 2014-02-19 17:03:05,875:26618(0x2b03a239b700):ZOO_INFO@log_env@712: Client
> environment:zookeeper.version=zookeeper C client 3.4.5
> 2014-02-19 17:03:05,875:26618(0x2b03a239b700):ZOO_INFO@log_env@716: Client
> environment:host.name=vesta.apache.org
> 2014-02-19 17:03:05,875:26618(0x2b03a239b700):ZOO_INFO@log_env@723: Client
> environment:os.name=Linux
> 2014-02-19 17:03:05,875:26618(0x2b03a239b700):ZOO_INFO@log_env@724: Client
> environment:os.arch=3.2.0-51-generic
> 2014-02-19 17:03:05,875:26618(0x2b03a239b700):ZOO_INFO@log_env@725: Client
> environment:os.version=#77-Ubuntu SMP Wed Jul 24 20:18:19 UTC 2013
> 2014-02-19 17:03:05,875:26618(0x2b03a239b700):ZOO_INFO@log_env@733: Client
> environment:user.name=(null)
> 2014-02-19 17:03:05,875:26618(0x2b03a239b700):ZOO_INFO@log_env@741: Client
> environment:user.home=/home/jenkins
> 2014-02-19 17:03:05,875:26618(0x2b03a239b700):ZOO_INFO@log_env@753: Client
> environment:user.dir=/home/hudson/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Set-JAVA_HOME/build/src
> 2014-02-19 17:03:05,875:26618(0x2b03a239b700):ZOO_INFO@zookeeper_init@786:
> Initiating client connection, host=127.0.0.1:56088 sessionTimeout=10000
> watcher=0x2b039f1252e0 sessionId=0 sessionPasswd=<null>
> context=0x2b03b401aac0 flags=0
> 2014-02-19 17:03:05,875:26618(0x2b03a1d98700):ZOO_INFO@log_env@712: Client
> environment:zookeeper.version=zookeeper C client 3.4.5
> 2014-02-19 17:03:05,875:26618(0x2b03a1d98700):ZOO_INFO@log_env@716: Client
> environment:host.name=vesta.apache.org
> 2014-02-19 17:03:05,875:26618(0x2b03a1d98700):ZOO_INFO@log_env@723: Client
> environment:os.name=Linux
> 2014-02-19 17:03:05,875:26618(0x2b03a1d98700):ZOO_INFO@log_env@724: Client
> environment:os.arch=3.2.0-51-generic
> 2014-02-19 17:03:05,875:26618(0x2b03a1d98700):ZOO_INFO@log_env@725: Client
> environment:os.version=#77-Ubuntu SMP Wed Jul 24 20:18:19 UTC 2013
> 2014-02-19 17:03:05,875:26618(0x2b03a1d98700):ZOO_INFO@log_env@733: Client
> environment:user.name=(null)
> I0219 17:03:05.875643 26852 master.cpp:250] Master started on
> 67.195.138.9:59606
> I0219 17:03:05.875682 26852 master.cpp:253] Master only allowing
> authenticated frameworks to register!
> I0219 17:03:05.876025 26851 master.cpp:86] No whitelist given. Advertising
> offers for all slaves
> I0219 17:03:05.876039 26854 hierarchical_allocator_process.hpp:302]
> Initializing hierarchical allocator process with master :
> [email protected]:59606
> 2014-02-19 17:03:05,875:26618(0x2b03a1d98700):ZOO_INFO@log_env@741: Client
> environment:user.home=/home/jenkins
> 2014-02-19 17:03:05,876:26618(0x2b03a1d98700):ZOO_INFO@log_env@753: Client
> environment:user.dir=/home/hudson/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Set-JAVA_HOME/build/src
> 2014-02-19 17:03:05,876:26618(0x2b03a1d98700):ZOO_INFO@zookeeper_init@786:
> Initiating client connection, host=127.0.0.1:56088 sessionTimeout=10000
> watcher=0x2b039f1252e0 sessionId=0 sessionPasswd=<null>
> context=0x2b03a802a9a0 flags=0
> 2014-02-19 17:03:05,876:26618(0x2b04e4200700):ZOO_INFO@check_events@1703:
> initiated connection to server [127.0.0.1:56088]
> I0219 17:03:05.876658 26852 contender.cpp:127] Joining the ZK group
> 2014-02-19 17:03:05,876:26618(0x2b0491cd2700):ZOO_INFO@check_events@1703:
> initiated connection to server [127.0.0.1:56088]
> 2014-02-19 17:03:05,894:26618(0x2b04e4200700):ZOO_INFO@check_events@1750:
> session establishment complete on server [127.0.0.1:56088],
> sessionId=0x1444b19c7bf0006, negotiated timeout=10000
> I0219 17:03:05.894346 26852 group.cpp:310] Group process
> ((2215)@67.195.138.9:59606) connected to ZooKeeper
> I0219 17:03:05.894397 26852 group.cpp:775] Syncing group operations: queue
> size (joins, cancels, datas) = (1, 0, 0)
> I0219 17:03:05.894405 26852 group.cpp:382] Trying to create path '/znode' in
> ZooKeeper
> 2014-02-19 17:03:05,894:26618(0x2b0491cd2700):ZOO_INFO@check_events@1750:
> session establishment complete on server [127.0.0.1:56088],
> sessionId=0x1444b19c7bf0007, negotiated timeout=10000
> I0219 17:03:05.894667 26854 group.cpp:310] Group process
> ((2217)@67.195.138.9:59606) connected to ZooKeeper
> I0219 17:03:05.894690 26854 group.cpp:775] Syncing group operations: queue
> size (joins, cancels, datas) = (0, 0, 0)
> I0219 17:03:05.894697 26854 group.cpp:382] Trying to create path '/znode' in
> ZooKeeper
> I0219 17:03:05.908177 26850 contender.cpp:243] New candidate (id='2') has
> entered the contest for leadership
> I0219 17:03:05.908455 26849 detector.cpp:134] Detected a new leader: (id='2')
> I0219 17:03:05.908638 26851 group.cpp:652] Trying to get
> '/znode/info_0000000002' in ZooKeeper
> I0219 17:03:05.909266 26854 detector.cpp:377] A new leading master
> ([email protected]:59606) is detected
> I0219 17:03:05.909405 26852 master.cpp:761] The newly elected leader is
> [email protected]:59606 with id 2014-02-19-17:03:05-160088899-59606-26618
> I0219 17:03:05.909421 26852 master.cpp:771] Elected as the leading master!
> 2014-02-19 17:03:05,909:26618(0x2b03a239b700):ZOO_INFO@log_env@712: Client
> environment:zookeeper.version=zookeeper C client 3.4.5
> 2014-02-19 17:03:05,909:26618(0x2b03a239b700):ZOO_INFO@log_env@716: Client
> environment:host.name=vesta.apache.org
> 2014-02-19 17:03:05,909:26618(0x2b03a239b700):ZOO_INFO@log_env@723: Client
> environment:os.name=Linux
> 2014-02-19 17:03:05,909:26618(0x2b03a239b700):ZOO_INFO@log_env@724: Client
> environment:os.arch=3.2.0-51-generic
> 2014-02-19 17:03:05,909:26618(0x2b03a239b700):ZOO_INFO@log_env@725: Client
> environment:os.version=#77-Ubuntu SMP Wed Jul 24 20:18:19 UTC 2013
> 2014-02-19 17:03:05,910:26618(0x2b03a239b700):ZOO_INFO@log_env@733: Client
> environment:user.name=(null)
> 2014-02-19 17:03:05,910:26618(0x2b03a239b700):ZOO_INFO@log_env@741: Client
> environment:user.home=/home/jenkins
> I0219 17:03:05.910152 26854 slave.cpp:112] Slave started on
> 142)@67.195.138.9:59606
> 2014-02-19 17:03:05,910:26618(0x2b03a239b700):ZOO_INFO@log_env@753: Client
> environment:user.dir=/home/hudson/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Set-JAVA_HOME/build/src
> 2014-02-19 17:03:05,910:26618(0x2b03a239b700):ZOO_INFO@zookeeper_init@786:
> Initiating client connection, host=127.0.0.1:56088 sessionTimeout=10000
> watcher=0x2b039f1252e0 sessionId=0 sessionPasswd=<null>
> context=0x2b03b402dbc0 flags=0
> I0219 17:03:05.910295 26854 slave.cpp:122] Slave resources: cpus(*):2;
> mem(*):1024; disk(*):1.38501e+06; ports(*):[31000-32000]
> I0219 17:03:05.910416 26854 slave.cpp:150] Slave hostname: vesta.apache.org
> I0219 17:03:05.910426 26854 slave.cpp:151] Slave checkpoint: false
> 2014-02-19 17:03:05,910:26618(0x2b03a1d98700):ZOO_INFO@log_env@712: Client
> environment:zookeeper.version=zookeeper C client 3.4.5
> 2014-02-19 17:03:05,910:26618(0x2b03a1d98700):ZOO_INFO@log_env@716: Client
> environment:host.name=vesta.apache.org
> 2014-02-19 17:03:05,910:26618(0x2b03a1d98700):ZOO_INFO@log_env@723: Client
> environment:os.name=Linux
> 2014-02-19 17:03:05,910:26618(0x2b03a1d98700):ZOO_INFO@log_env@724: Client
> environment:os.arch=3.2.0-51-generic
> 2014-02-19 17:03:05,910:26618(0x2b03a1d98700):ZOO_INFO@log_env@725: Client
> environment:os.version=#77-Ubuntu SMP Wed Jul 24 20:18:19 UTC 2013
> I0219 17:03:05.910444 26618 sched.cpp:121] Version: 0.19.0
> 2014-02-19 17:03:05,910:26618(0x2b03a1d98700):ZOO_INFO@log_env@733: Client
> environment:user.name=(null)
> 2014-02-19 17:03:05,910:26618(0x2b0491ed3700):ZOO_INFO@check_events@1703:
> initiated connection to server [127.0.0.1:56088]
> 2014-02-19 17:03:05,910:26618(0x2b03a1d98700):ZOO_INFO@log_env@741: Client
> environment:user.home=/home/jenkins
> 2014-02-19 17:03:05,910:26618(0x2b03a1d98700):ZOO_INFO@log_env@753: Client
> environment:user.dir=/home/hudson/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Set-JAVA_HOME/build/src
> 2014-02-19 17:03:05,910:26618(0x2b03a1d98700):ZOO_INFO@zookeeper_init@786:
> Initiating client connection, host=127.0.0.1:56088 sessionTimeout=10000
> watcher=0x2b039f1252e0 sessionId=0 sessionPasswd=<null>
> context=0x2b03a802d890 flags=0
> 2014-02-19 17:03:05,910:26618(0x2b04910bb700):ZOO_INFO@check_events@1703:
> initiated connection to server [127.0.0.1:56088]
> I0219 17:03:05.911613 26852 state.cpp:33] Recovering state from
> '/tmp/AllocatorZooKeeperTest_0_SlaveReregistersFirst_p6MmsU/meta'
> I0219 17:03:05.911772 26852 status_update_manager.cpp:188] Recovering status
> update manager
> I0219 17:03:05.911883 26852 slave.cpp:2670] Finished recovery
> 2014-02-19 17:03:05,925:26618(0x2b0491ed3700):ZOO_INFO@check_events@1750:
> session establishment complete on server [127.0.0.1:56088],
> sessionId=0x1444b19c7bf0008, negotiated timeout=10000
> 2014-02-19 17:03:05,926:26618(0x2b04910bb700):ZOO_INFO@check_events@1750:
> session establishment complete on server [127.0.0.1:56088],
> sessionId=0x1444b19c7bf0009, negotiated timeout=10000
> I0219 17:03:05.926594 26852 group.cpp:310] Group process
> ((2221)@67.195.138.9:59606) connected to ZooKeeper
> I0219 17:03:05.927129 26852 group.cpp:775] Syncing group operations: queue
> size (joins, cancels, datas) = (0, 0, 0)
> I0219 17:03:05.927137 26852 group.cpp:382] Trying to create path '/znode' in
> ZooKeeper
> I0219 17:03:05.927199 26850 group.cpp:310] Group process
> ((2227)@67.195.138.9:59606) connected to ZooKeeper
> I0219 17:03:05.927214 26850 group.cpp:775] Syncing group operations: queue
> size (joins, cancels, datas) = (0, 0, 0)
> I0219 17:03:05.927222 26850 group.cpp:382] Trying to create path '/znode' in
> ZooKeeper
> I0219 17:03:05.928433 26854 detector.cpp:134] Detected a new leader: (id='2')
> I0219 17:03:05.928577 26850 detector.cpp:134] Detected a new leader: (id='2')
> I0219 17:03:05.928653 26854 group.cpp:652] Trying to get
> '/znode/info_0000000002' in ZooKeeper
> I0219 17:03:05.928778 26855 group.cpp:652] Trying to get
> '/znode/info_0000000002' in ZooKeeper
> I0219 17:03:05.929374 26849 detector.cpp:377] A new leading master
> ([email protected]:59606) is detected
> I0219 17:03:05.929484 26855 detector.cpp:377] A new leading master
> ([email protected]:59606) is detected
> I0219 17:03:05.929491 26854 sched.cpp:217] New master detected at
> [email protected]:59606
> I0219 17:03:05.929518 26854 sched.cpp:267] Authenticating with master
> [email protected]:59606
> I0219 17:03:05.929595 26849 authenticatee.hpp:124] Creating new client SASL
> connection
> I0219 17:03:05.929627 26853 slave.cpp:397] New master detected at
> [email protected]:59606
> I0219 17:03:05.929707 26853 slave.cpp:422] Detecting new master
> I0219 17:03:05.929710 26849 status_update_manager.cpp:162] New master
> detected at [email protected]:59606
> I0219 17:03:05.929715 26851 master.cpp:2344] Authenticating framework at
> scheduler(135)@67.195.138.9:59606
> I0219 17:03:05.929797 26849 authenticator.hpp:140] Creating new server SASL
> connection
> I0219 17:03:05.929842 26851 master.cpp:1848] Attempting to register slave on
> vesta.apache.org at slave(142)@67.195.138.9:59606
> I0219 17:03:05.929872 26851 master.cpp:2831] Adding slave
> 2014-02-19-17:03:05-160088899-59606-26618-0 at vesta.apache.org with
> cpus(*):2; mem(*):1024; disk(*):1.38501e+06; ports(*):[31000-32000]
> I0219 17:03:05.929890 26854 authenticatee.hpp:212] Received SASL
> authentication mechanisms: CRAM-MD5
> I0219 17:03:05.929916 26854 authenticatee.hpp:238] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0219 17:03:05.929949 26849 slave.cpp:440] Registered with master
> [email protected]:59606; given slave ID
> 2014-02-19-17:03:05-160088899-59606-26618-0
> I0219 17:03:05.929957 26854 authenticator.hpp:243] Received SASL
> authentication start
> I0219 17:03:05.930044 26854 authenticator.hpp:325] Authentication requires
> more steps
> I0219 17:03:05.930076 26854 authenticatee.hpp:258] Received SASL
> authentication step
> I0219 17:03:05.930063 26853 hierarchical_allocator_process.hpp:445] Added
> slave 2014-02-19-17:03:05-160088899-59606-26618-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)
> I0219 17:03:05.930142 26853 hierarchical_allocator_process.hpp:708] Performed
> allocation for slave 2014-02-19-17:03:05-160088899-59606-26618-0 in 10649ns
> I0219 17:03:05.930150 26854 authenticator.hpp:271] Received SASL
> authentication step
> I0219 17:03:05.930178 26854 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
> I0219 17:03:05.930192 26854 auxprop.cpp:153] Looking up auxiliary property
> '*userPassword'
> I0219 17:03:05.930207 26854 auxprop.cpp:153] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0219 17:03:05.930217 26854 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
> I0219 17:03:05.930224 26854 auxprop.cpp:103] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0219 17:03:05.930229 26854 auxprop.cpp:103] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0219 17:03:05.930240 26854 authenticator.hpp:317] Authentication success
> I0219 17:03:05.930294 26855 authenticatee.hpp:298] Authentication success
> I0219 17:03:05.930325 26853 master.cpp:2384] Successfully authenticated
> framework at scheduler(135)@67.195.138.9:59606
> I0219 17:03:05.930433 26855 sched.cpp:341] Successfully authenticated with
> master [email protected]:59606
> I0219 17:03:05.930445 26855 sched.cpp:460] Sending registration request to
> [email protected]:59606
> I0219 17:03:05.930541 26853 master.cpp:819] Received registration request
> from scheduler(135)@67.195.138.9:59606
> I0219 17:03:05.930567 26853 master.cpp:837] Registering framework
> 2014-02-19-17:03:05-160088899-59606-26618-0000 at
> scheduler(135)@67.195.138.9:59606
> I0219 17:03:05.930646 26854 sched.cpp:391] Framework registered with
> 2014-02-19-17:03:05-160088899-59606-26618-0000
> I0219 17:03:05.930675 26854 sched.cpp:405] Scheduler::registered took 11470ns
> I0219 17:03:05.930680 26849 hierarchical_allocator_process.hpp:332] Added
> framework 2014-02-19-17:03:05-160088899-59606-26618-0000
> I0219 17:03:05.930757 26849 hierarchical_allocator_process.hpp:752] Offering
> cpus(*):2; mem(*):1024; disk(*):1.38501e+06; ports(*):[31000-32000] on slave
> 2014-02-19-17:03:05-160088899-59606-26618-0 to framework
> 2014-02-19-17:03:05-160088899-59606-26618-0000
> I0219 17:03:05.930902 26849 hierarchical_allocator_process.hpp:688] Performed
> allocation for 1 slaves in 199357ns
> I0219 17:03:05.930982 26852 master.hpp:446] Adding offer
> 2014-02-19-17:03:05-160088899-59606-26618-0 with resources cpus(*):2;
> mem(*):1024; disk(*):1.38501e+06; ports(*):[31000-32000] on slave
> 2014-02-19-17:03:05-160088899-59606-26618-0 (vesta.apache.org)
> I0219 17:03:05.931045 26852 master.cpp:2299] Sending 1 offers to framework
> 2014-02-19-17:03:05-160088899-59606-26618-0000
> I0219 17:03:05.931311 26853 sched.cpp:528] Scheduler::resourceOffers took
> 172750ns
> I0219 17:03:05.931478 26852 master.hpp:456] Removing offer
> 2014-02-19-17:03:05-160088899-59606-26618-0 with resources cpus(*):2;
> mem(*):1024; disk(*):1.38501e+06; ports(*):[31000-32000] on slave
> 2014-02-19-17:03:05-160088899-59606-26618-0 (vesta.apache.org)
> I0219 17:03:05.931529 26852 master.cpp:1575] Processing reply for offers: [
> 2014-02-19-17:03:05-160088899-59606-26618-0 ] on slave
> 2014-02-19-17:03:05-160088899-59606-26618-0 (vesta.apache.org) for framework
> 2014-02-19-17:03:05-160088899-59606-26618-0000
> I0219 17:03:05.931607 26852 master.hpp:418] Adding task 0 with resources
> cpus(*):1; mem(*):500 on slave 2014-02-19-17:03:05-160088899-59606-26618-0
> (vesta.apache.org)
> I0219 17:03:05.931633 26852 master.cpp:2468] Launching task 0 of framework
> 2014-02-19-17:03:05-160088899-59606-26618-0000 with resources cpus(*):1;
> mem(*):500 on slave 2014-02-19-17:03:05-160088899-59606-26618-0
> (vesta.apache.org)
> I0219 17:03:05.931709 26853 slave.cpp:625] Got assigned task 0 for framework
> 2014-02-19-17:03:05-160088899-59606-26618-0000
> I0219 17:03:05.931768 26854 hierarchical_allocator_process.hpp:547] Framework
> 2014-02-19-17:03:05-160088899-59606-26618-0000 left cpus(*):1; mem(*):524;
> disk(*):1.38501e+06; ports(*):[31000-32000] unused on slave
> 2014-02-19-17:03:05-160088899-59606-26618-0
> I0219 17:03:05.931888 26854 hierarchical_allocator_process.hpp:590] Framework
> 2014-02-19-17:03:05-160088899-59606-26618-0000 filtered slave
> 2014-02-19-17:03:05-160088899-59606-26618-0 for 5secs
> I0219 17:03:05.931891 26853 slave.cpp:734] Launching task 0 for framework
> 2014-02-19-17:03:05-160088899-59606-26618-0000
> I0219 17:03:05.938443 26853 exec.cpp:131] Version: 0.19.0
> I0219 17:03:05.938510 26850 exec.cpp:181] Executor started at:
> executor(46)@67.195.138.9:59606 with pid 26618
> I0219 17:03:05.938557 26853 slave.cpp:844] Queuing task '0' for executor
> default of framework '2014-02-19-17:03:05-160088899-59606-26618-0000
> I0219 17:03:05.938618 26853 slave.cpp:358] Successfully attached file
> '/tmp/AllocatorZooKeeperTest_0_SlaveReregistersFirst_p6MmsU/slaves/2014-02-19-17:03:05-160088899-59606-26618-0/frameworks/2014-02-19-17:03:05-160088899-59606-26618-0000/executors/default/runs/e7e22faf-12db-40ea-827b-d0efa42bba62'
> I0219 17:03:05.938640 26853 slave.cpp:1989] Monitoring executor 'default' of
> framework '2014-02-19-17:03:05-160088899-59606-26618-0000' in container
> 'e7e22faf-12db-40ea-827b-d0efa42bba62'
> I0219 17:03:05.938700 26853 slave.cpp:1316] Got registration for executor
> 'default' of framework 2014-02-19-17:03:05-160088899-59606-26618-0000
> I0219 17:03:05.938822 26853 slave.cpp:1434] Flushing queued task 0 for
> executor 'default' of framework 2014-02-19-17:03:05-160088899-59606-26618-0000
> I0219 17:03:05.938830 26855 exec.cpp:205] Executor registered on slave
> 2014-02-19-17:03:05-160088899-59606-26618-0
> I0219 17:03:05.940070 26855 exec.cpp:217] Executor::registered took 9088ns
> I0219 17:03:05.940114 26855 exec.cpp:292] Executor asked to run task '0'
> I0219 17:03:05.940161 26855 exec.cpp:301] Executor::launchTask took 35877ns
> I0219 17:03:05.941411 26855 exec.cpp:524] Executor sending status update
> TASK_RUNNING (UUID: 6ca49dbb-8ebf-491f-9b6d-f24416b5d44d) for task 0 of
> framework 2014-02-19-17:03:05-160088899-59606-26618-0000
> I0219 17:03:05.941478 26855 slave.cpp:1643] Handling status update
> TASK_RUNNING (UUID: 6ca49dbb-8ebf-491f-9b6d-f24416b5d44d) for task 0 of
> framework 2014-02-19-17:03:05-160088899-59606-26618-0000 from
> executor(46)@67.195.138.9:59606
> I0219 17:03:05.941572 26854 status_update_manager.cpp:315] Received status
> update TASK_RUNNING (UUID: 6ca49dbb-8ebf-491f-9b6d-f24416b5d44d) for task 0
> of framework 2014-02-19-17:03:05-160088899-59606-26618-0000
> I0219 17:03:05.941596 26854 status_update_manager.cpp:494] Creating
> StatusUpdate stream for task 0 of framework
> 2014-02-19-17:03:05-160088899-59606-26618-0000
> I0219 17:03:05.941681 26854 status_update_manager.cpp:368] Forwarding status
> update TASK_RUNNING (UUID: 6ca49dbb-8ebf-491f-9b6d-f24416b5d44d) for task 0
> of framework 2014-02-19-17:03:05-160088899-59606-26618-0000 to
> [email protected]:59606
> I0219 17:03:05.941830 26851 slave.cpp:1763] Status update manager
> successfully handled status update TASK_RUNNING (UUID:
> 6ca49dbb-8ebf-491f-9b6d-f24416b5d44d) for task 0 of framework
> 2014-02-19-17:03:05-160088899-59606-26618-0000
> I0219 17:03:05.941861 26851 slave.cpp:1769] Sending acknowledgement for
> status update TASK_RUNNING (UUID: 6ca49dbb-8ebf-491f-9b6d-f24416b5d44d) for
> task 0 of framework 2014-02-19-17:03:05-160088899-59606-26618-0000 to
> executor(46)@67.195.138.9:59606
> I0219 17:03:05.941872 26855 master.cpp:2031] Status update TASK_RUNNING
> (UUID: 6ca49dbb-8ebf-491f-9b6d-f24416b5d44d) for task 0 of framework
> 2014-02-19-17:03:05-160088899-59606-26618-0000 from
> slave(142)@67.195.138.9:59606
> I0219 17:03:05.941918 26850 exec.cpp:338] Executor received status update
> acknowledgement 6ca49dbb-8ebf-491f-9b6d-f24416b5d44d for task 0 of framework
> 2014-02-19-17:03:05-160088899-59606-26618-0000
> I0219 17:03:05.941964 26854 sched.cpp:619] Scheduler::statusUpdate took
> 31021ns
> I0219 17:03:05.942229 26618 master.cpp:518] Master terminating
> I0219 17:03:05.942267 26618 master.hpp:436] Removing task 0 with resources
> cpus(*):1; mem(*):500 on slave 2014-02-19-17:03:05-160088899-59606-26618-0
> (vesta.apache.org)
> I0219 17:03:05.942287 26850 status_update_manager.cpp:393] Received status
> update acknowledgement (UUID: 6ca49dbb-8ebf-491f-9b6d-f24416b5d44d) for task
> 0 of framework 2014-02-19-17:03:05-160088899-59606-26618-0000
> I0219 17:03:05.942380 26854 slave.cpp:1256] Status update manager
> successfully handled status update acknowledgement (UUID:
> 6ca49dbb-8ebf-491f-9b6d-f24416b5d44d) for task 0 of framework
> 2014-02-19-17:03:05-160088899-59606-26618-0000
> I0219 17:03:05.942391 26851 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
> 2014-02-19-17:03:05-160088899-59606-26618-0 from framework
> 2014-02-19-17:03:05-160088899-59606-26618-0000
> I0219 17:03:05.942616 26852 slave.cpp:1844] [email protected]:59606 exited
> W0219 17:03:05.942668 26852 slave.cpp:1847] Master disconnected! Waiting for
> a new master to be elected
> I0219 17:03:06.048465 26851 contender.cpp:182] Now cancelling the membership:
> 2
> I0219 17:03:06.048564 26851 group.cpp:613] Trying to remove
> '/znode/info_0000000002' in ZooKeeper
> 2014-02-19 17:03:06,061:26618(0x2b03a19927c0):ZOO_INFO@zookeeper_close@2505:
> Closing zookeeper sessionId=0x1444b19c7bf0006 to [127.0.0.1:56088]
> I0219 17:03:06.062000 26851 detector.cpp:122] The current leader (id=2) is
> lost
> I0219 17:03:06.062021 26851 detector.cpp:134] Detected a new leader: None
> I0219 17:03:06.062201 26855 sched.cpp:211] Scheduler::disconnected took
> 10980ns
> I0219 17:03:06.062222 26855 sched.cpp:233] No master detected
> I0219 17:03:06.062365 26855 detector.cpp:122] The current leader (id=2) is
> lost
> 2014-02-19 17:03:06,062:26618(0x2b03a19927c0):ZOO_INFO@zookeeper_close@2505:
> Closing zookeeper sessionId=0x1444b19c7bf0007 to [127.0.0.1:56088]
> I0219 17:03:06.062377 26855 detector.cpp:134] Detected a new leader: None
> I0219 17:03:06.062521 26855 slave.cpp:418] Lost leading master
> I0219 17:03:06.062536 26855 slave.cpp:422] Detecting new master
> 2014-02-19 17:03:06,062:26618(0x2b03a239b700):ZOO_INFO@log_env@712: Client
> environment:zookeeper.version=zookeeper C client 3.4.5
> 2014-02-19 17:03:06,062:26618(0x2b03a1d98700):ZOO_INFO@log_env@712: Client
> environment:zookeeper.version=zookeeper C client 3.4.5
> 2014-02-19 17:03:06,063:26618(0x2b03a1d98700):ZOO_INFO@log_env@716: Client
> environment:host.name=vesta.apache.org
> 2014-02-19 17:03:06,063:26618(0x2b03a1d98700):ZOO_INFO@log_env@723: Client
> environment:os.name=Linux
> 2014-02-19 17:03:06,063:26618(0x2b03a1d98700):ZOO_INFO@log_env@724: Client
> environment:os.arch=3.2.0-51-generic
> 2014-02-19 17:03:06,063:26618(0x2b03a1d98700):ZOO_INFO@log_env@725: Client
> environment:os.version=#77-Ubuntu SMP Wed Jul 24 20:18:19 UTC 2013
> I0219 17:03:06.063132 26618 master.cpp:240] Master ID:
> 2014-02-19-17:03:06-160088899-59606-26618 Hostname: vesta.apache.org
> 2014-02-19 17:03:06,063:26618(0x2b03a239b700):ZOO_INFO@log_env@716: Client
> environment:host.name=vesta.apache.org
> 2014-02-19 17:03:06,063:26618(0x2b03a239b700):ZOO_INFO@log_env@723: Client
> environment:os.name=Linux
> 2014-02-19 17:03:06,063:26618(0x2b03a239b700):ZOO_INFO@log_env@724: Client
> environment:os.arch=3.2.0-51-generic
> 2014-02-19 17:03:06,063:26618(0x2b03a239b700):ZOO_INFO@log_env@725: Client
> environment:os.version=#77-Ubuntu SMP Wed Jul 24 20:18:19 UTC 2013
> I0219 17:03:06.063208 26851 master.cpp:250] Master started on
> 67.195.138.9:59606
> I0219 17:03:06.063222 26851 master.cpp:253] Master only allowing
> authenticated frameworks to register!
> 2014-02-19 17:03:06,063:26618(0x2b03a1d98700):ZOO_INFO@log_env@733: Client
> environment:user.name=(null)
> 2014-02-19 17:03:06,063:26618(0x2b03a239b700):ZOO_INFO@log_env@733: Client
> environment:user.name=(null)
> 2014-02-19 17:03:06,063:26618(0x2b03a1d98700):ZOO_INFO@log_env@741: Client
> environment:user.home=/home/jenkins
> 2014-02-19 17:03:06,063:26618(0x2b03a1d98700):ZOO_INFO@log_env@753: Client
> environment:user.dir=/home/hudson/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Set-JAVA_HOME/build/src
> 2014-02-19 17:03:06,063:26618(0x2b03a1d98700):ZOO_INFO@zookeeper_init@786:
> Initiating client connection, host=127.0.0.1:56088 sessionTimeout=10000
> watcher=0x2b039f1252e0 sessionId=0 sessionPasswd=<null>
> context=0x2b03a801e230 flags=0
> 2014-02-19 17:03:06,063:26618(0x2b03a239b700):ZOO_INFO@log_env@741: Client
> environment:user.home=/home/jenkins
> 2014-02-19 17:03:06,063:26618(0x2b03a239b700):ZOO_INFO@log_env@753: Client
> environment:user.dir=/home/hudson/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Set-JAVA_HOME/build/src
> 2014-02-19 17:03:06,063:26618(0x2b03a239b700):ZOO_INFO@zookeeper_init@786:
> Initiating client connection, host=127.0.0.1:56088 sessionTimeout=10000
> watcher=0x2b039f1252e0 sessionId=0 sessionPasswd=<null>
> context=0x2b03b4020390 flags=0
> I0219 17:03:06.063695 26854 master.cpp:86] No whitelist given. Advertising
> offers for all slaves
> 2014-02-19 17:03:06,063:26618(0x2b04918d0700):ZOO_INFO@check_events@1703:
> initiated connection to server [127.0.0.1:56088]
> I0219 17:03:06.063774 26854 hierarchical_allocator_process.hpp:302]
> Initializing hierarchical allocator process with master :
> [email protected]:59606
> 2014-02-19 17:03:06,063:26618(0x2b04928fa700):ZOO_INFO@check_events@1703:
> initiated connection to server [127.0.0.1:56088]
> I0219 17:03:06.063882 26852 contender.cpp:127] Joining the ZK group
> 2014-02-19 17:03:06,085:26618(0x2b04918d0700):ZOO_INFO@check_events@1750:
> session establishment complete on server [127.0.0.1:56088],
> sessionId=0x1444b19c7bf000a, negotiated timeout=10000
> I0219 17:03:06.085342 26851 group.cpp:310] Group process
> ((2234)@67.195.138.9:59606) connected to ZooKeeper
> I0219 17:03:06.085366 26851 group.cpp:775] Syncing group operations: queue
> size (joins, cancels, datas) = (0, 0, 0)
> I0219 17:03:06.085378 26851 group.cpp:382] Trying to create path '/znode' in
> ZooKeeper
> 2014-02-19 17:03:06,085:26618(0x2b04928fa700):ZOO_INFO@check_events@1750:
> session establishment complete on server [127.0.0.1:56088],
> sessionId=0x1444b19c7bf000b, negotiated timeout=10000
> I0219 17:03:06.085963 26850 group.cpp:310] Group process
> ((2232)@67.195.138.9:59606) connected to ZooKeeper
> I0219 17:03:06.085988 26850 group.cpp:775] Syncing group operations: queue
> size (joins, cancels, datas) = (1, 0, 0)
> I0219 17:03:06.085996 26850 group.cpp:382] Trying to create path '/znode' in
> ZooKeeper
> I0219 17:03:06.095528 26848 contender.cpp:243] New candidate (id='3') has
> entered the contest for leadership
> I0219 17:03:06.095865 26849 detector.cpp:134] Detected a new leader: (id='3')
> I0219 17:03:06.096199 26852 detector.cpp:134] Detected a new leader: (id='3')
> I0219 17:03:06.096401 26852 group.cpp:652] Trying to get
> '/znode/info_0000000003' in ZooKeeper
> I0219 17:03:06.096580 26848 detector.cpp:134] Detected a new leader: (id='3')
> I0219 17:03:06.096705 26848 group.cpp:652] Trying to get
> '/znode/info_0000000003' in ZooKeeper
> I0219 17:03:06.096758 26850 group.cpp:652] Trying to get
> '/znode/info_0000000003' in ZooKeeper
> I0219 17:03:06.097044 26852 detector.cpp:377] A new leading master
> ([email protected]:59606) is detected
> I0219 17:03:06.097118 26852 sched.cpp:217] New master detected at
> [email protected]:59606
> I0219 17:03:06.097143 26852 sched.cpp:267] Authenticating with master
> [email protected]:59606
> I0219 17:03:06.097231 26849 authenticatee.hpp:124] Creating new client SASL
> connection
> W0219 17:03:06.097342 26852 master.cpp:2314] Ignoring authenticate message
> from authenticatee(150)@67.195.138.9:59606 since not elected yet
> I0219 17:03:06.097615 26854 detector.cpp:377] A new leading master
> ([email protected]:59606) is detected
> I0219 17:03:06.097695 26851 slave.cpp:397] New master detected at
> [email protected]:59606
> I0219 17:03:06.097718 26850 detector.cpp:377] A new leading master
> ([email protected]:59606) is detected
> I0219 17:03:06.097753 26850 status_update_manager.cpp:162] New master
> detected at [email protected]:59606
> I0219 17:03:06.097789 26850 master.cpp:761] The newly elected leader is
> [email protected]:59606 with id 2014-02-19-17:03:06-160088899-59606-26618
> I0219 17:03:06.097798 26851 slave.cpp:422] Detecting new master
> I0219 17:03:06.097801 26850 master.cpp:771] Elected as the leading master!
> I0219 17:03:06.097980 26850 master.cpp:1942] Attempting to re-register slave
> 2014-02-19-17:03:05-160088899-59606-26618-0 at slave(142)@67.195.138.9:59606
> (vesta.apache.org)
> I0219 17:03:06.097991 26850 master.cpp:2831] Adding slave
> 2014-02-19-17:03:05-160088899-59606-26618-0 at vesta.apache.org with
> cpus(*):2; mem(*):1024; disk(*):1.38501e+06; ports(*):[31000-32000]
> I0219 17:03:06.098089 26853 slave.cpp:490] Re-registered with master
> [email protected]:59606
> I0219 17:03:06.098099 26850 master.hpp:418] Adding task 0 with resources
> cpus(*):1; mem(*):500 on slave 2014-02-19-17:03:05-160088899-59606-26618-0
> (vesta.apache.org)
> W0219 17:03:06.098136 26850 master.cpp:2926] Possibly orphaned task 0 of
> framework 2014-02-19-17:03:05-160088899-59606-26618-0000 running on slave
> 2014-02-19-17:03:05-160088899-59606-26618-0 (vesta.apache.org)
> GMOCK WARNING:
> Uninteresting mock function call - taking default action specified at:
> ../../src/tests/mesos.hpp:416:
> Function call: slaveAdded(@0x2b03bc036b20
> 2014-02-19-17:03:05-160088899-59606-26618-0, @0x2b03bc036ab0 hostname:
> "vesta.apache.org"
> webui_hostname: "vesta.apache.org"
> resources {
> name: "cpus"
> type: SCALAR
> scalar {
> value: 2
> }
> role: "*"
> }
> resources {
> name: "mem"
> type: SCALAR
> scalar {
> value: 1024
> }
> role: "*"
> }
> resources {
> name: "disk"
> type: SCALAR
> scalar {
> value: 1385007
> }
> role: "*"
> }
> resources {
> name: "ports"
> type: RANGES
> ranges {
> range {
> begin: 31000
> end: 32000
> }
> }
> role: "*"
> }
> id {
> value: "2014-02-19-17:03:05-160088899-59606-26618-0"
> }
> checkpoint: false
> port: 59606
> , @0x2b03bc036a80 { (2014-02-19-17:03:05-160088899-59606-26618-0000, {
> cpus(*):1, mem(*):500 }) })
> Stack trace:
> I0219 17:03:06.098511 26851 hierarchical_allocator_process.hpp:445] Added
> slave 2014-02-19-17:03:05-160088899-59606-26618-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)
> I0219 17:03:06.098551 26851 hierarchical_allocator_process.hpp:708] Performed
> allocation for slave 2014-02-19-17:03:05-160088899-59606-26618-0 in 9395ns
> I0219 17:03:07.064607 26854 hierarchical_allocator_process.hpp:688] Performed
> allocation for 1 slaves in 28419ns
> I0219 17:03:08.065130 26850 hierarchical_allocator_process.hpp:688] Performed
> allocation for 1 slaves in 26533ns
> 2014-02-19
> 17:03:08,930:26618(0x2b0491ad1700):ZOO_ERROR@handle_socket_error_msg@1697:
> Socket [127.0.0.1:36062] zk retcode=-4, errno=111(Connection refused): server
> refused to accept the client
> I0219 17:03:09.065291 26853 hierarchical_allocator_process.hpp:688] Performed
> allocation for 1 slaves in 24552ns
> I0219 17:03:10.066000 26852 hierarchical_allocator_process.hpp:688] Performed
> allocation for 1 slaves in 28299ns
> I0219 17:03:11.064774 26855 master.cpp:86] No whitelist given. Advertising
> offers for all slaves
> I0219 17:03:11.066874 26853 hierarchical_allocator_process.hpp:688] Performed
> allocation for 1 slaves in 38463ns
> W0219 17:03:11.098078 26851 sched.cpp:362] Authentication timed out
> I0219 17:03:11.098212 26851 sched.cpp:322] Failed to authenticate with master
> [email protected]:59606: future discarded
> I0219 17:03:11.098263 26851 sched.cpp:267] Authenticating with master
> [email protected]:59606
> I0219 17:03:11.098418 26849 authenticatee.hpp:124] Creating new client SASL
> connection
> I0219 17:03:11.098618 26854 master.cpp:2344] Authenticating framework at
> scheduler(135)@67.195.138.9:59606
> I0219 17:03:11.098731 26849 authenticator.hpp:140] Creating new server SASL
> connection
> I0219 17:03:11.098847 26849 authenticatee.hpp:212] Received SASL
> authentication mechanisms: CRAM-MD5
> I0219 17:03:11.098861 26849 authenticatee.hpp:238] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0219 17:03:11.098901 26849 authenticator.hpp:243] Received SASL
> authentication start
> I0219 17:03:11.098995 26849 authenticator.hpp:325] Authentication requires
> more steps
> I0219 17:03:11.099023 26849 authenticatee.hpp:258] Received SASL
> authentication step
> I0219 17:03:11.099135 26848 authenticator.hpp:271] Received SASL
> authentication step
> I0219 17:03:11.099171 26848 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
> I0219 17:03:11.099180 26848 auxprop.cpp:153] Looking up auxiliary property
> '*userPassword'
> I0219 17:03:11.099195 26848 auxprop.cpp:153] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0219 17:03:11.099206 26848 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
> I0219 17:03:11.099213 26848 auxprop.cpp:103] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0219 17:03:11.099218 26848 auxprop.cpp:103] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0219 17:03:11.099233 26848 authenticator.hpp:317] Authentication success
> I0219 17:03:11.099287 26848 authenticatee.hpp:298] Authentication success
> I0219 17:03:11.099309 26849 master.cpp:2384] Successfully authenticated
> framework at scheduler(135)@67.195.138.9:59606
> I0219 17:03:11.099447 26848 sched.cpp:341] Successfully authenticated with
> master [email protected]:59606
> I0219 17:03:11.099462 26848 sched.cpp:460] Sending registration request to
> [email protected]:59606
> I0219 17:03:12.067173 26853 hierarchical_allocator_process.hpp:688] Performed
> allocation for 1 slaves in 30034ns
> I0219 17:03:12.100287 26850 sched.cpp:460] Sending registration request to
> [email protected]:59606
> 2014-02-19
> 17:03:12,266:26618(0x2b0491ad1700):ZOO_ERROR@handle_socket_error_msg@1697:
> Socket [127.0.0.1:36062] zk retcode=-4, errno=111(Connection refused): server
> refused to accept the client
> I0219 17:03:13.067528 26848 hierarchical_allocator_process.hpp:688] Performed
> allocation for 1 slaves in 27983ns
> I0219 17:03:13.100697 26850 sched.cpp:460] Sending registration request to
> [email protected]:59606
> I0219 17:03:14.067955 26854 hierarchical_allocator_process.hpp:688] Performed
> allocation for 1 slaves in 21896ns
> I0219 17:03:14.101096 26852 sched.cpp:460] Sending registration request to
> [email protected]:59606
> I0219 17:03:15.069147 26853 hierarchical_allocator_process.hpp:688] Performed
> allocation for 1 slaves in 36762ns
> I0219 17:03:15.102193 26852 sched.cpp:460] Sending registration request to
> [email protected]:59606
> 2014-02-19
> 17:03:15,603:26618(0x2b0491ad1700):ZOO_ERROR@handle_socket_error_msg@1697:
> Socket [127.0.0.1:36062] zk retcode=-4, errno=111(Connection refused): server
> refused to accept the client
> I0219 17:03:16.065767 26848 master.cpp:86] No whitelist given. Advertising
> offers for all slaves
> I0219 17:03:16.069912 26850 hierarchical_allocator_process.hpp:688] Performed
> allocation for 1 slaves in 40382ns
> ../../src/tests/allocator_zookeeper_tests.cpp:290: Failure
> Failed to wait 10secs for slaveAdded
> ../../src/tests/allocator_zookeeper_tests.cpp:284: Failure
> Actual function call count doesn't match EXPECT_CALL(allocator2,
> slaveAdded(_, _, _))...
> Expected: to be called once
> Actual: never called - unsatisfied and active
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.1.5#6160)
