You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@mesos.apache.org by "Yan Xu (JIRA)" <ji...@apache.org> on 2014/03/13 06:38:43 UTC
[jira] [Created] (MESOS-1089)
AllocatorZooKeeperTest/0.SlaveReregistersFirst is flaky
Yan Xu created MESOS-1089:
-----------------------------
Summary: AllocatorZooKeeperTest/0.SlaveReregistersFirst is flaky
Key: MESOS-1089
URL: https://issues.apache.org/jira/browse/MESOS-1089
Project: Mesos
Issue Type: Bug
Components: test
Reporter: Yan Xu
Fix For: 0.19.0
{code}
[ RUN ] AllocatorZooKeeperTest/0.SlaveReregistersFirst
2014-03-12 19:43:17,315:18527(0x2b8793868700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
2014-03-12 19:43:17,315:18527(0x2b8792e63700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
2014-03-12 19:43:17,315:18527(0x2b8792e63700):ZOO_INFO@log_env@716: Client environment:host.name=juno
2014-03-12 19:43:17,315:18527(0x2b8792e63700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
2014-03-12 19:43:17,315:18527(0x2b8792e63700):ZOO_INFO@log_env@724: Client environment:os.arch=3.2.0-51-generic
2014-03-12 19:43:17,315:18527(0x2b8792e63700):ZOO_INFO@log_env@725: Client environment:os.version=#77-Ubuntu SMP Wed Jul 24 20:18:19 UTC 2013
I0312 19:43:17.315152 18527 master.cpp:254] Master ID: 2014-03-12-19:43:17-1032504131-34563-18527 Hostname: juno.apache.org
2014-03-12 19:43:17,315:18527(0x2b8793868700):ZOO_INFO@log_env@716: Client environment:host.name=juno
2014-03-12 19:43:17,315:18527(0x2b8793868700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
2014-03-12 19:43:17,315:18527(0x2b8793868700):ZOO_INFO@log_env@724: Client environment:os.arch=3.2.0-51-generic
2014-03-12 19:43:17,315:18527(0x2b8793868700):ZOO_INFO@log_env@725: Client environment:os.version=#77-Ubuntu SMP Wed Jul 24 20:18:19 UTC 2013
I0312 19:43:17.315193 18684 master.cpp:264] Master started on 67.195.138.61:34563
I0312 19:43:17.315275 18684 master.cpp:267] Master only allowing authenticated frameworks to register!
2014-03-12 19:43:17,315:18527(0x2b8792e63700):ZOO_INFO@log_env@733: Client environment:user.name=(null)
2014-03-12 19:43:17,315:18527(0x2b8793868700):ZOO_INFO@log_env@733: Client environment:user.name=(null)
2014-03-12 19:43:17,315:18527(0x2b8792e63700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
2014-03-12 19:43:17,315:18527(0x2b8793868700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
2014-03-12 19:43:17,315:18527(0x2b8793868700):ZOO_INFO@log_env@753: Client environment:user.dir=/home/jenkins/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/src
2014-03-12 19:43:17,315:18527(0x2b8793868700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:38228 sessionTimeout=10000 watcher=0x2b87901bbd20 sessionId=0 sessionPasswd=<null> context=0x2b87980082e0 flags=0
I0312 19:43:17.315691 18687 master.cpp:98] No whitelist given. Advertising offers for all slaves
I0312 19:43:17.315896 18688 hierarchical_allocator_process.hpp:302] Initializing hierarchical allocator process with master : master@67.195.138.61:34563
2014-03-12 19:43:17,315:18527(0x2b8792e63700):ZOO_INFO@log_env@753: Client environment:user.dir=/home/jenkins/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/src
2014-03-12 19:43:17,316:18527(0x2b8792e63700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:38228 sessionTimeout=10000 watcher=0x2b87901bbd20 sessionId=0 sessionPasswd=<null> context=0x2b87b8027570 flags=0
2014-03-12 19:43:17,316:18527(0x2b891956c700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:38228]
I0312 19:43:17.316247 18686 contender.cpp:127] Joining the ZK group
2014-03-12 19:43:17,316:18527(0x2b891a7ad700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:38228]
2014-03-12 19:43:17,410:18527(0x2b891956c700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:38228], sessionId=0x144b7d1fca00006, negotiated timeout=10000
I0312 19:43:17.411078 18684 group.cpp:310] Group process ((2257)@67.195.138.61:34563) connected to ZooKeeper
I0312 19:43:17.411095 18684 group.cpp:778] Syncing group operations: queue size (joins, cancels, datas) = (1, 0, 0)
I0312 19:43:17.411104 18684 group.cpp:382] Trying to create path '/znode' in ZooKeeper
2014-03-12 19:43:17,411:18527(0x2b891a7ad700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:38228], sessionId=0x144b7d1fca00007, negotiated timeout=10000
I0312 19:43:17.411546 18687 group.cpp:310] Group process ((2259)@67.195.138.61:34563) connected to ZooKeeper
I0312 19:43:17.411563 18687 group.cpp:778] Syncing group operations: queue size (joins, cancels, datas) = (0, 0, 0)
I0312 19:43:17.411571 18687 group.cpp:382] Trying to create path '/znode' in ZooKeeper
I0312 19:43:17.435623 18686 contender.cpp:243] New candidate (id='2') has entered the contest for leadership
I0312 19:43:17.435928 18690 detector.cpp:134] Detected a new leader: (id='2')
I0312 19:43:17.436125 18690 group.cpp:655] Trying to get '/znode/info_0000000002' in ZooKeeper
I0312 19:43:17.436746 18690 detector.cpp:377] A new leading master (UPID=master@67.195.138.61:34563) is detected
I0312 19:43:17.436841 18685 master.cpp:773] The newly elected leader is master@67.195.138.61:34563 with id 2014-03-12-19:43:17-1032504131-34563-18527
I0312 19:43:17.436872 18685 master.cpp:783] Elected as the leading master!
2014-03-12 19:43:17,437:18527(0x2b8792e63700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
2014-03-12 19:43:17,437:18527(0x2b8792e63700):ZOO_INFO@log_env@716: Client environment:host.name=juno
2014-03-12 19:43:17,437:18527(0x2b8792e63700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
2014-03-12 19:43:17,437:18527(0x2b8792e63700):ZOO_INFO@log_env@724: Client environment:os.arch=3.2.0-51-generic
2014-03-12 19:43:17,437:18527(0x2b8792e63700):ZOO_INFO@log_env@725: Client environment:os.version=#77-Ubuntu SMP Wed Jul 24 20:18:19 UTC 2013
2014-03-12 19:43:17,437:18527(0x2b8792e63700):ZOO_INFO@log_env@733: Client environment:user.name=(null)
2014-03-12 19:43:17,437:18527(0x2b8792e63700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
2014-03-12 19:43:17,437:18527(0x2b8792e63700):ZOO_INFO@log_env@753: Client environment:user.dir=/home/jenkins/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/src
2014-03-12 19:43:17,437:18527(0x2b8792e63700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:38228 sessionTimeout=10000 watcher=0x2b87901bbd20 sessionId=0 sessionPasswd=<null> context=0x2b87b8022b30 flags=0
I0312 19:43:17.437845 18527 sched.cpp:121] Version: 0.19.0
2014-03-12 19:43:17,437:18527(0x2b8793265700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
2014-03-12 19:43:17,437:18527(0x2b8793265700):ZOO_INFO@log_env@716: Client environment:host.name=juno
2014-03-12 19:43:17,437:18527(0x2b8793265700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
2014-03-12 19:43:17,437:18527(0x2b8793265700):ZOO_INFO@log_env@724: Client environment:os.arch=3.2.0-51-generic
2014-03-12 19:43:17,437:18527(0x2b8793265700):ZOO_INFO@log_env@725: Client environment:os.version=#77-Ubuntu SMP Wed Jul 24 20:18:19 UTC 2013
I0312 19:43:17.437872 18688 slave.cpp:120] Slave started on 143)@67.195.138.61:34563
2014-03-12 19:43:17,438:18527(0x2b8793265700):ZOO_INFO@log_env@733: Client environment:user.name=(null)
2014-03-12 19:43:17,438:18527(0x2b8793265700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
I0312 19:43:17.438099 18688 slave.cpp:130] Slave resources: cpus(*):2; mem(*):1024; disk(*):23038; ports(*):[31000-32000]
2014-03-12 19:43:17,438:18527(0x2b8793265700):ZOO_INFO@log_env@753: Client environment:user.dir=/home/jenkins/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/src
2014-03-12 19:43:17,438:18527(0x2b8793265700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:38228 sessionTimeout=10000 watcher=0x2b87901bbd20 sessionId=0 sessionPasswd=<null> context=0x2b87a4038630 flags=0
I0312 19:43:17.438199 18688 slave.cpp:158] Slave hostname: juno.apache.org
I0312 19:43:17.438218 18688 slave.cpp:159] Slave checkpoint: false
2014-03-12 19:43:17,438:18527(0x2b8919fa9700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:38228]
2014-03-12 19:43:17,438:18527(0x2b891a3ab700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:38228]
I0312 19:43:17.438670 18688 state.cpp:33] Recovering state from '/tmp/AllocatorZooKeeperTest_0_SlaveReregistersFirst_LaXNS9/meta'
I0312 19:43:17.438796 18688 status_update_manager.cpp:193] Recovering status update manager
I0312 19:43:17.438953 18686 slave.cpp:2707] Finished recovery
2014-03-12 19:43:17,461:18527(0x2b8919fa9700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:38228], sessionId=0x144b7d1fca00008, negotiated timeout=10000
I0312 19:43:17.461163 18686 group.cpp:310] Group process ((2263)@67.195.138.61:34563) connected to ZooKeeper
I0312 19:43:17.461179 18686 group.cpp:778] Syncing group operations: queue size (joins, cancels, datas) = (0, 0, 0)
I0312 19:43:17.461189 18686 group.cpp:382] Trying to create path '/znode' in ZooKeeper
2014-03-12 19:43:17,494:18527(0x2b891a3ab700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:38228], sessionId=0x144b7d1fca00009, negotiated timeout=10000
I0312 19:43:17.494899 18690 group.cpp:310] Group process ((2269)@67.195.138.61:34563) connected to ZooKeeper
I0312 19:43:17.494915 18690 group.cpp:778] Syncing group operations: queue size (joins, cancels, datas) = (0, 0, 0)
I0312 19:43:17.494925 18690 group.cpp:382] Trying to create path '/znode' in ZooKeeper
I0312 19:43:17.495162 18686 detector.cpp:134] Detected a new leader: (id='2')
I0312 19:43:17.495321 18686 group.cpp:655] Trying to get '/znode/info_0000000002' in ZooKeeper
I0312 19:43:17.496093 18686 detector.cpp:377] A new leading master (UPID=master@67.195.138.61:34563) is detected
I0312 19:43:17.496196 18691 slave.cpp:405] New master detected at master@67.195.138.61:34563
I0312 19:43:17.496294 18686 detector.cpp:134] Detected a new leader: (id='2')
I0312 19:43:17.496335 18691 slave.cpp:430] Detecting new master
I0312 19:43:17.496348 18686 status_update_manager.cpp:167] New master detected at master@67.195.138.61:34563
I0312 19:43:17.496459 18686 master.cpp:1885] Attempting to register slave on juno.apache.org at slave(143)@67.195.138.61:34563
I0312 19:43:17.496480 18686 master.cpp:2869] Adding slave 2014-03-12-19:43:17-1032504131-34563-18527-0 at juno.apache.org with cpus(*):2; mem(*):1024; disk(*):23038; ports(*):[31000-32000]
I0312 19:43:17.496497 18688 group.cpp:655] Trying to get '/znode/info_0000000002' in ZooKeeper
I0312 19:43:17.496553 18691 slave.cpp:448] Registered with master master@67.195.138.61:34563; given slave ID 2014-03-12-19:43:17-1032504131-34563-18527-0
I0312 19:43:17.496664 18687 hierarchical_allocator_process.hpp:445] Added slave 2014-03-12-19:43:17-1032504131-34563-18527-0 (juno.apache.org) with cpus(*):2; mem(*):1024; disk(*):23038; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):23038; ports(*):[31000-32000] available)
I0312 19:43:17.496709 18687 hierarchical_allocator_process.hpp:708] Performed allocation for slave 2014-03-12-19:43:17-1032504131-34563-18527-0 in 7224ns
I0312 19:43:17.497156 18686 detector.cpp:377] A new leading master (UPID=master@67.195.138.61:34563) is detected
I0312 19:43:17.497267 18688 sched.cpp:217] New master detected at master@67.195.138.61:34563
I0312 19:43:17.497295 18688 sched.cpp:267] Authenticating with master master@67.195.138.61:34563
I0312 19:43:17.497376 18686 authenticatee.hpp:128] Creating new client SASL connection
I0312 19:43:17.497536 18690 master.cpp:2382] Authenticating framework at scheduler(136)@67.195.138.61:34563
I0312 19:43:17.497617 18686 authenticator.hpp:148] Creating new server SASL connection
I0312 19:43:17.497728 18686 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
I0312 19:43:17.497753 18686 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
I0312 19:43:17.497786 18686 authenticator.hpp:254] Received SASL authentication start
I0312 19:43:17.497854 18686 authenticator.hpp:342] Authentication requires more steps
I0312 19:43:17.497892 18686 authenticatee.hpp:265] Received SASL authentication step
I0312 19:43:17.497943 18686 authenticator.hpp:282] Received SASL authentication step
I0312 19:43:17.497969 18686 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'juno.apache.org' server FQDN: 'juno.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0312 19:43:17.497978 18686 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I0312 19:43:17.497992 18686 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0312 19:43:17.498003 18686 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'juno.apache.org' server FQDN: 'juno.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0312 19:43:17.498011 18686 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0312 19:43:17.498018 18686 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0312 19:43:17.498030 18686 authenticator.hpp:334] Authentication success
I0312 19:43:17.498067 18686 authenticatee.hpp:305] Authentication success
I0312 19:43:17.498123 18684 master.cpp:2422] Successfully authenticated framework at scheduler(136)@67.195.138.61:34563
I0312 19:43:17.498178 18686 sched.cpp:341] Successfully authenticated with master master@67.195.138.61:34563
I0312 19:43:17.498193 18686 sched.cpp:460] Sending registration request to master@67.195.138.61:34563
I0312 19:43:17.498308 18684 master.cpp:831] Received registration request from scheduler(136)@67.195.138.61:34563
I0312 19:43:17.498347 18684 master.cpp:849] Registering framework 2014-03-12-19:43:17-1032504131-34563-18527-0000 at scheduler(136)@67.195.138.61:34563
I0312 19:43:17.498437 18690 sched.cpp:391] Framework registered with 2014-03-12-19:43:17-1032504131-34563-18527-0000
I0312 19:43:17.498466 18684 hierarchical_allocator_process.hpp:332] Added framework 2014-03-12-19:43:17-1032504131-34563-18527-0000
I0312 19:43:17.498469 18690 sched.cpp:405] Scheduler::registered took 10416ns
I0312 19:43:17.498534 18684 hierarchical_allocator_process.hpp:752] Offering cpus(*):2; mem(*):1024; disk(*):23038; ports(*):[31000-32000] on slave 2014-03-12-19:43:17-1032504131-34563-18527-0 to framework 2014-03-12-19:43:17-1032504131-34563-18527-0000
I0312 19:43:17.498688 18684 hierarchical_allocator_process.hpp:688] Performed allocation for 1 slaves in 202093ns
I0312 19:43:17.498759 18691 master.hpp:456] Adding offer 2014-03-12-19:43:17-1032504131-34563-18527-0 with resources cpus(*):2; mem(*):1024; disk(*):23038; ports(*):[31000-32000] on slave 2014-03-12-19:43:17-1032504131-34563-18527-0 (juno.apache.org)
I0312 19:43:17.498821 18691 master.cpp:2337] Sending 1 offers to framework 2014-03-12-19:43:17-1032504131-34563-18527-0000
I0312 19:43:17.499151 18688 sched.cpp:528] Scheduler::resourceOffers took 201610ns
I0312 19:43:17.499358 18691 master.hpp:466] Removing offer 2014-03-12-19:43:17-1032504131-34563-18527-0 with resources cpus(*):2; mem(*):1024; disk(*):23038; ports(*):[31000-32000] on slave 2014-03-12-19:43:17-1032504131-34563-18527-0 (juno.apache.org)
I0312 19:43:17.499425 18691 master.cpp:1611] Processing reply for offers: [ 2014-03-12-19:43:17-1032504131-34563-18527-0 ] on slave 2014-03-12-19:43:17-1032504131-34563-18527-0 (juno.apache.org) for framework 2014-03-12-19:43:17-1032504131-34563-18527-0000
I0312 19:43:17.499517 18691 master.hpp:428] Adding task 0 with resources cpus(*):1; mem(*):500 on slave 2014-03-12-19:43:17-1032504131-34563-18527-0 (juno.apache.org)
I0312 19:43:17.499554 18691 master.cpp:2506] Launching task 0 of framework 2014-03-12-19:43:17-1032504131-34563-18527-0000 with resources cpus(*):1; mem(*):500 on slave 2014-03-12-19:43:17-1032504131-34563-18527-0 (juno.apache.org)
I0312 19:43:17.499655 18688 slave.cpp:666] Got assigned task 0 for framework 2014-03-12-19:43:17-1032504131-34563-18527-0000
I0312 19:43:17.499706 18690 hierarchical_allocator_process.hpp:547] Framework 2014-03-12-19:43:17-1032504131-34563-18527-0000 left cpus(*):1; mem(*):524; disk(*):23038; ports(*):[31000-32000] unused on slave 2014-03-12-19:43:17-1032504131-34563-18527-0
I0312 19:43:17.499842 18690 hierarchical_allocator_process.hpp:590] Framework 2014-03-12-19:43:17-1032504131-34563-18527-0000 filtered slave 2014-03-12-19:43:17-1032504131-34563-18527-0 for 5secs
I0312 19:43:17.499871 18688 slave.cpp:775] Launching task 0 for framework 2014-03-12-19:43:17-1032504131-34563-18527-0000
I0312 19:43:17.503469 18688 exec.cpp:131] Version: 0.19.0
I0312 19:43:17.503545 18687 exec.cpp:181] Executor started at: executor(47)@67.195.138.61:34563 with pid 18527
I0312 19:43:17.503597 18688 slave.cpp:885] Queuing task '0' for executor default of framework '2014-03-12-19:43:17-1032504131-34563-18527-0000
I0312 19:43:17.503654 18688 slave.cpp:366] Successfully attached file '/tmp/AllocatorZooKeeperTest_0_SlaveReregistersFirst_LaXNS9/slaves/2014-03-12-19:43:17-1032504131-34563-18527-0/frameworks/2014-03-12-19:43:17-1032504131-34563-18527-0000/executors/default/runs/a834e1a5-12c6-4cef-a10f-404d2c8b3ed2'
I0312 19:43:17.503693 18688 slave.cpp:2026] Monitoring executor 'default' of framework '2014-03-12-19:43:17-1032504131-34563-18527-0000' in container 'a834e1a5-12c6-4cef-a10f-404d2c8b3ed2'
I0312 19:43:17.503763 18688 slave.cpp:1357] Got registration for executor 'default' of framework 2014-03-12-19:43:17-1032504131-34563-18527-0000
I0312 19:43:17.503885 18688 slave.cpp:1475] Flushing queued task 0 for executor 'default' of framework 2014-03-12-19:43:17-1032504131-34563-18527-0000
I0312 19:43:17.503921 18690 exec.cpp:205] Executor registered on slave 2014-03-12-19:43:17-1032504131-34563-18527-0
I0312 19:43:17.505468 18690 exec.cpp:217] Executor::registered took 15897ns
I0312 19:43:17.505530 18690 exec.cpp:292] Executor asked to run task '0'
I0312 19:43:17.505573 18690 exec.cpp:301] Executor::launchTask took 21401ns
I0312 19:43:17.507102 18690 exec.cpp:524] Executor sending status update TASK_RUNNING (UUID: ae4696e3-e5bf-4059-bd8c-428cf3734fc2) for task 0 of framework 2014-03-12-19:43:17-1032504131-34563-18527-0000
I0312 19:43:17.507189 18690 slave.cpp:1684] Handling status update TASK_RUNNING (UUID: ae4696e3-e5bf-4059-bd8c-428cf3734fc2) for task 0 of framework 2014-03-12-19:43:17-1032504131-34563-18527-0000 from executor(47)@67.195.138.61:34563
I0312 19:43:17.507289 18687 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: ae4696e3-e5bf-4059-bd8c-428cf3734fc2) for task 0 of framework 2014-03-12-19:43:17-1032504131-34563-18527-0000
I0312 19:43:17.507310 18687 status_update_manager.cpp:499] Creating StatusUpdate stream for task 0 of framework 2014-03-12-19:43:17-1032504131-34563-18527-0000
I0312 19:43:17.507364 18687 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: ae4696e3-e5bf-4059-bd8c-428cf3734fc2) for task 0 of framework 2014-03-12-19:43:17-1032504131-34563-18527-0000 to master@67.195.138.61:34563
I0312 19:43:17.507488 18690 master.cpp:2069] Status update TASK_RUNNING (UUID: ae4696e3-e5bf-4059-bd8c-428cf3734fc2) for task 0 of framework 2014-03-12-19:43:17-1032504131-34563-18527-0000 from slave(143)@67.195.138.61:34563
I0312 19:43:17.507500 18684 slave.cpp:1800] Status update manager successfully handled status update TASK_RUNNING (UUID: ae4696e3-e5bf-4059-bd8c-428cf3734fc2) for task 0 of framework 2014-03-12-19:43:17-1032504131-34563-18527-0000
I0312 19:43:17.507526 18684 slave.cpp:1806] Sending acknowledgement for status update TASK_RUNNING (UUID: ae4696e3-e5bf-4059-bd8c-428cf3734fc2) for task 0 of framework 2014-03-12-19:43:17-1032504131-34563-18527-0000 to executor(47)@67.195.138.61:34563
I0312 19:43:17.507570 18687 sched.cpp:619] Scheduler::statusUpdate took 18332ns
I0312 19:43:17.507599 18685 exec.cpp:338] Executor received status update acknowledgement ae4696e3-e5bf-4059-bd8c-428cf3734fc2 for task 0 of framework 2014-03-12-19:43:17-1032504131-34563-18527-0000
I0312 19:43:17.507825 18688 status_update_manager.cpp:398] Received status update acknowledgement (UUID: ae4696e3-e5bf-4059-bd8c-428cf3734fc2) for task 0 of framework 2014-03-12-19:43:17-1032504131-34563-18527-0000
I0312 19:43:17.507829 18527 master.cpp:530] Master terminating
I0312 19:43:17.507905 18688 slave.cpp:1297] Status update manager successfully handled status update acknowledgement (UUID: ae4696e3-e5bf-4059-bd8c-428cf3734fc2) for task 0 of framework 2014-03-12-19:43:17-1032504131-34563-18527-0000
I0312 19:43:17.507910 18527 master.hpp:446] Removing task 0 with resources cpus(*):1; mem(*):500 on slave 2014-03-12-19:43:17-1032504131-34563-18527-0 (juno.apache.org)
I0312 19:43:17.508035 18685 hierarchical_allocator_process.hpp:637] Recovered cpus(*):1; mem(*):500 (total allocatable: cpus(*):2; mem(*):1024; disk(*):23038; ports(*):[31000-32000]) on slave 2014-03-12-19:43:17-1032504131-34563-18527-0 from framework 2014-03-12-19:43:17-1032504131-34563-18527-0000
I0312 19:43:17.508390 18691 slave.cpp:1881] master@67.195.138.61:34563 exited
W0312 19:43:17.508412 18691 slave.cpp:1884] Master disconnected! Waiting for a new master to be elected
I0312 19:43:17.509906 18527 contender.cpp:182] Now cancelling the membership: 2
I0312 19:43:17.510033 18684 group.cpp:616] Trying to remove '/znode/info_0000000002' in ZooKeeper
2014-03-12 19:43:17,523:18527(0x2b8792a5d7c0):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x144b7d1fca00006 to [127.0.0.1:38228]
2014-03-12 19:43:17,523:18527(0x2b8792a5d7c0):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x144b7d1fca00007 to [127.0.0.1:38228]
I0312 19:43:17.524593 18685 detector.cpp:122] The current leader (id=2) is lost
I0312 19:43:17.524615 18685 detector.cpp:134] Detected a new leader: None
I0312 19:43:17.524613 18689 detector.cpp:122] The current leader (id=2) is lost
2014-03-12 19:43:17,524:18527(0x2b8793064700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
I0312 19:43:17.524638 18689 detector.cpp:134] Detected a new leader: None
2014-03-12 19:43:17,524:18527(0x2b8793064700):ZOO_INFO@log_env@716: Client environment:host.name=juno
2014-03-12 19:43:17,524:18527(0x2b8793064700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
2014-03-12 19:43:17,524:18527(0x2b8793064700):ZOO_INFO@log_env@724: Client environment:os.arch=3.2.0-51-generic
2014-03-12 19:43:17,524:18527(0x2b8793064700):ZOO_INFO@log_env@725: Client environment:os.version=#77-Ubuntu SMP Wed Jul 24 20:18:19 UTC 2013
I0312 19:43:17.524718 18527 master.cpp:254] Master ID: 2014-03-12-19:43:17-1032504131-34563-18527 Hostname: juno.apache.org
2014-03-12 19:43:17,524:18527(0x2b8792e63700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
2014-03-12 19:43:17,524:18527(0x2b8792e63700):ZOO_INFO@log_env@716: Client environment:host.name=juno
2014-03-12 19:43:17,524:18527(0x2b8792e63700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
2014-03-12 19:43:17,524:18527(0x2b8792e63700):ZOO_INFO@log_env@724: Client environment:os.arch=3.2.0-51-generic
2014-03-12 19:43:17,524:18527(0x2b8792e63700):ZOO_INFO@log_env@725: Client environment:os.version=#77-Ubuntu SMP Wed Jul 24 20:18:19 UTC 2013
2014-03-12 19:43:17,524:18527(0x2b8793064700):ZOO_INFO@log_env@733: Client environment:user.name=(null)
I0312 19:43:17.524904 18689 slave.cpp:426] Lost leading master
I0312 19:43:17.524929 18689 slave.cpp:430] Detecting new master
2014-03-12 19:43:17,524:18527(0x2b8793064700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
I0312 19:43:17.524991 18689 master.cpp:264] Master started on 67.195.138.61:34563
2014-03-12 19:43:17,525:18527(0x2b8793064700):ZOO_INFO@log_env@753: Client environment:user.dir=/home/jenkins/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/src
2014-03-12 19:43:17,525:18527(0x2b8793064700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:38228 sessionTimeout=10000 watcher=0x2b87901bbd20 sessionId=0 sessionPasswd=<null> context=0x2b87a801eae0 flags=0
2014-03-12 19:43:17,525:18527(0x2b8792e63700):ZOO_INFO@log_env@733: Client environment:user.name=(null)
I0312 19:43:17.525017 18689 master.cpp:267] Master only allowing authenticated frameworks to register!
I0312 19:43:17.525065 18691 sched.cpp:211] Scheduler::disconnected took 9993ns
2014-03-12 19:43:17,525:18527(0x2b8792e63700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
I0312 19:43:17.525168 18691 sched.cpp:233] No master detected
2014-03-12 19:43:17,525:18527(0x2b8792e63700):ZOO_INFO@log_env@753: Client environment:user.dir=/home/jenkins/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/src
2014-03-12 19:43:17,525:18527(0x2b8792e63700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:38228 sessionTimeout=10000 watcher=0x2b87901bbd20 sessionId=0 sessionPasswd=<null> context=0x2b87b800f010 flags=0
2014-03-12 19:43:17,525:18527(0x2b891a5ac700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:38228]
I0312 19:43:17.525538 18691 master.cpp:98] No whitelist given. Advertising offers for all slaves
2014-03-12 19:43:17,525:18527(0x2b8918d58700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:38228]
I0312 19:43:17.525720 18685 hierarchical_allocator_process.hpp:302] Initializing hierarchical allocator process with master : master@67.195.138.61:34563
I0312 19:43:17.525753 18689 contender.cpp:127] Joining the ZK group
2014-03-12 19:43:17,584:18527(0x2b891a5ac700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:38228], sessionId=0x144b7d1fca0000a, negotiated timeout=10000
I0312 19:43:17.584198 18689 group.cpp:310] Group process ((2274)@67.195.138.61:34563) connected to ZooKeeper
I0312 19:43:17.584218 18689 group.cpp:778] Syncing group operations: queue size (joins, cancels, datas) = (1, 0, 0)
I0312 19:43:17.584226 18689 group.cpp:382] Trying to create path '/znode' in ZooKeeper
2014-03-12 19:43:17,584:18527(0x2b8918d58700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:38228], sessionId=0x144b7d1fca0000b, negotiated timeout=10000
I0312 19:43:17.584748 18685 group.cpp:310] Group process ((2276)@67.195.138.61:34563) connected to ZooKeeper
I0312 19:43:17.584761 18685 group.cpp:778] Syncing group operations: queue size (joins, cancels, datas) = (0, 0, 0)
I0312 19:43:17.584769 18685 group.cpp:382] Trying to create path '/znode' in ZooKeeper
I0312 19:43:17.619072 18684 contender.cpp:243] New candidate (id='3') has entered the contest for leadership
I0312 19:43:17.619726 18684 detector.cpp:134] Detected a new leader: (id='3')
I0312 19:43:17.619952 18690 group.cpp:655] Trying to get '/znode/info_0000000003' in ZooKeeper
I0312 19:43:17.620018 18684 detector.cpp:134] Detected a new leader: (id='3')
I0312 19:43:17.620246 18689 group.cpp:655] Trying to get '/znode/info_0000000003' in ZooKeeper
I0312 19:43:17.620671 18685 detector.cpp:134] Detected a new leader: (id='3')
I0312 19:43:17.620806 18686 group.cpp:655] Trying to get '/znode/info_0000000003' in ZooKeeper
I0312 19:43:17.621136 18691 detector.cpp:377] A new leading master (UPID=master@67.195.138.61:34563) is detected
I0312 19:43:17.621209 18691 sched.cpp:217] New master detected at master@67.195.138.61:34563
I0312 19:43:17.621229 18691 sched.cpp:267] Authenticating with master master@67.195.138.61:34563
I0312 19:43:17.621322 18688 authenticatee.hpp:128] Creating new client SASL connection
W0312 19:43:17.621480 18685 master.cpp:2352] Ignoring authenticate message from authenticatee(150)@67.195.138.61:34563 since not elected yet
I0312 19:43:17.621616 18684 detector.cpp:377] A new leading master (UPID=master@67.195.138.61:34563) is detected
I0312 19:43:17.621728 18690 detector.cpp:377] A new leading master (UPID=master@67.195.138.61:34563) is detected
I0312 19:43:17.621774 18686 slave.cpp:405] New master detected at master@67.195.138.61:34563
I0312 19:43:17.621808 18685 master.cpp:773] The newly elected leader is master@67.195.138.61:34563 with id 2014-03-12-19:43:17-1032504131-34563-18527
I0312 19:43:17.621824 18685 master.cpp:783] Elected as the leading master!
I0312 19:43:17.621845 18684 status_update_manager.cpp:167] New master detected at master@67.195.138.61:34563
I0312 19:43:17.621906 18686 slave.cpp:430] Detecting new master
I0312 19:43:17.621964 18685 master.cpp:1980] Attempting to re-register slave 2014-03-12-19:43:17-1032504131-34563-18527-0 at slave(143)@67.195.138.61:34563 (juno.apache.org)
I0312 19:43:17.621980 18685 master.cpp:2869] Adding slave 2014-03-12-19:43:17-1032504131-34563-18527-0 at juno.apache.org with cpus(*):2; mem(*):1024; disk(*):23038; ports(*):[31000-32000]
I0312 19:43:17.622063 18686 slave.cpp:498] Re-registered with master master@67.195.138.61:34563
I0312 19:43:17.622076 18685 master.hpp:428] Adding task 0 with resources cpus(*):1; mem(*):500 on slave 2014-03-12-19:43:17-1032504131-34563-18527-0 (juno.apache.org)
W0312 19:43:17.622107 18685 master.cpp:2965] Possibly orphaned task 0 of framework 2014-03-12-19:43:17-1032504131-34563-18527-0000 running on slave 2014-03-12-19:43:17-1032504131-34563-18527-0 (juno.apache.org)
GMOCK WARNING:
Uninteresting mock function call - taking default action specified at:
./tests/mesos.hpp:424:
Function call: slaveAdded(@0x2b87b8040f50 2014-03-12-19:43:17-1032504131-34563-18527-0, @0x2b87b8040ee0 hostname: "juno.apache.org"
webui_hostname: "juno.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: 23038
}
role: "*"
}
resources {
name: "ports"
type: RANGES
ranges {
range {
begin: 31000
end: 32000
}
}
role: "*"
}
id {
value: "2014-03-12-19:43:17-1032504131-34563-18527-0"
}
checkpoint: false
port: 34563
, @0x2b87b8040eb0 { (2014-03-12-19:43:17-1032504131-34563-18527-0000, { cpus(*):1, mem(*):500 }) })
Stack trace:
I0312 19:43:17.622601 18685 hierarchical_allocator_process.hpp:445] Added slave 2014-03-12-19:43:17-1032504131-34563-18527-0 (juno.apache.org) with cpus(*):2; mem(*):1024; disk(*):23038; ports(*):[31000-32000] (and cpus(*):1; mem(*):524; disk(*):23038; ports(*):[31000-32000] available)
I0312 19:43:17.622648 18685 hierarchical_allocator_process.hpp:708] Performed allocation for slave 2014-03-12-19:43:17-1032504131-34563-18527-0 in 8238ns
I0312 19:43:18.526563 18689 hierarchical_allocator_process.hpp:688] Performed allocation for 1 slaves in 16134ns
I0312 19:43:19.526924 18691 hierarchical_allocator_process.hpp:688] Performed allocation for 1 slaves in 28730ns
2014-03-12 19:43:20,340:18527(0x2b891996e700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:39171] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
I0312 19:43:20.527256 18688 hierarchical_allocator_process.hpp:688] Performed allocation for 1 slaves in 27283ns
I0312 19:43:21.528138 18684 hierarchical_allocator_process.hpp:688] Performed allocation for 1 slaves in 28706ns
I0312 19:43:22.525884 18690 master.cpp:98] No whitelist given. Advertising offers for all slaves
I0312 19:43:22.529023 18691 hierarchical_allocator_process.hpp:688] Performed allocation for 1 slaves in 22973ns
W0312 19:43:22.622232 18687 sched.cpp:362] Authentication timed out
I0312 19:43:22.622361 18687 sched.cpp:322] Failed to authenticate with master master@67.195.138.61:34563: Authentication discarded
I0312 19:43:22.622400 18687 sched.cpp:267] Authenticating with master master@67.195.138.61:34563
I0312 19:43:22.622532 18684 authenticatee.hpp:128] Creating new client SASL connection
I0312 19:43:22.622774 18687 master.cpp:2382] Authenticating framework at scheduler(136)@67.195.138.61:34563
I0312 19:43:22.622859 18684 authenticator.hpp:148] Creating new server SASL connection
I0312 19:43:22.622985 18689 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
I0312 19:43:22.623004 18689 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
I0312 19:43:22.623038 18689 authenticator.hpp:254] Received SASL authentication start
I0312 19:43:22.623111 18689 authenticator.hpp:342] Authentication requires more steps
I0312 19:43:22.623142 18689 authenticatee.hpp:265] Received SASL authentication step
I0312 19:43:22.623208 18691 authenticator.hpp:282] Received SASL authentication step
I0312 19:43:22.623245 18691 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'juno.apache.org' server FQDN: 'juno.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0312 19:43:22.623258 18691 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I0312 19:43:22.623273 18691 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0312 19:43:22.623286 18691 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'juno.apache.org' server FQDN: 'juno.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0312 19:43:22.623294 18691 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0312 19:43:22.623299 18691 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0312 19:43:22.623317 18691 authenticator.hpp:334] Authentication success
I0312 19:43:22.623359 18684 authenticatee.hpp:305] Authentication success
I0312 19:43:22.623376 18691 master.cpp:2422] Successfully authenticated framework at scheduler(136)@67.195.138.61:34563
I0312 19:43:22.623440 18684 sched.cpp:341] Successfully authenticated with master master@67.195.138.61:34563
I0312 19:43:22.623461 18684 sched.cpp:460] Sending registration request to master@67.195.138.61:34563
I0312 19:43:23.529403 18691 hierarchical_allocator_process.hpp:688] Performed allocation for 1 slaves in 23699ns
I0312 19:43:23.624521 18688 sched.cpp:460] Sending registration request to master@67.195.138.61:34563
2014-03-12 19:43:23,676:18527(0x2b891996e700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:39171] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
I0312 19:43:24.529695 18684 hierarchical_allocator_process.hpp:688] Performed allocation for 1 slaves in 26288ns
I0312 19:43:24.624841 18688 sched.cpp:460] Sending registration request to master@67.195.138.61:34563
I0312 19:43:25.529984 18685 hierarchical_allocator_process.hpp:688] Performed allocation for 1 slaves in 28142ns
I0312 19:43:25.625077 18686 sched.cpp:460] Sending registration request to master@67.195.138.61:34563
I0312 19:43:26.530828 18689 hierarchical_allocator_process.hpp:688] Performed allocation for 1 slaves in 20700ns
I0312 19:43:26.625977 18688 sched.cpp:460] Sending registration request to master@67.195.138.61:34563
2014-03-12 19:43:27,012:18527(0x2b891996e700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:39171] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
I0312 19:43:27.526388 18688 master.cpp:98] No whitelist given. Advertising offers for all slaves
I0312 19:43:27.531579 18686 hierarchical_allocator_process.hpp:688] Performed allocation for 1 slaves in 26447ns
tests/allocator_zookeeper_tests.cpp:290: Failure
Failed to wait 10secs for slaveAdded
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
I0312 19:43:27.626893 18684 sched.cpp:460] Sending registration request to master@67.195.138.61:34563
I0312 19:43:28.627651 18684 sched.cpp:460] Sending registration request to master@67.195.138.61:34563
I0312 19:43:29.627825 18689 sched.cpp:460] Sending registration request to master@67.195.138.61:34563
2014-03-12 19:43:30,349:18527(0x2b891996e700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:39171] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
I0312 19:43:30.627961 18689 sched.cpp:460] Sending registration request to master@67.195.138.61:34563
{code}
The last few lines repeats forever. See [full log|https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/1693/consoleText].
--
This message was sent by Atlassian JIRA
(v6.2#6252)