[
https://issues.apache.org/jira/browse/ZOOKEEPER-2577?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16097835#comment-16097835
]
ASF GitHub Bot commented on ZOOKEEPER-2577:
-------------------------------------------
GitHub user hanm opened a pull request:
https://github.com/apache/zookeeper/pull/315
ZOOKEEPER-2577: Fix flaky testDuringLeaderSync test.
testDuringLeaderSync uses the presence of intermediate zoo.cfg.dynamic file
to decide if the reconfig operation was succeeded or not. This is not a problem
and is logically correct, however in tests that provisions QuorumPeer directly
through MainThread, the configFile will be null and the resulted intermediate
dynamic reconfig file will has a name of "null.cfg.dynamic". This causes
problem because multiple test cases use MainThread to provision QuorumPeer so
these tests will share a single "null.cfg.dynamic" file, as opposed to the
zoo.cfg.dynamic file in their specific test folder when configFile was not
null. Since we support running concurrent ant unit tests in apache build
infrastructure, it is highly likely that multiple tests that rely on this
shared null.cfg.dynamic file will execute simultaneously which create all sorts
of failure cases (this also explains why if one tries to reproduce the test
failures in a standalone fashion the test will always pass, with the absence of
the file sharing.).
This is problematic in multiple test cases and in particular cause this
testDuringLeaderSync fail fairly frequently. There are multiple solutions to
this problem:
* Implement retry with timeout logic when detecting the presence of
intermediate config files in testDuringLeaderSync. This will fix this specific
test but the fix is non-deterministic and other tests might still fail because
of sharing of null.cfg.dynamic file.
* Always make sure to to feed a real config file when provision QuorumPeer.
This however is an overkill as some cases a pure artificial QuorumPeer w/o real
config file fit the use case well.
* The approach used in this patch: when generating intermediate config
files if configFile is null, generate a random unique file name. This code path
is supposed to only active when executing unit tests.
Testing done: running this patch on apache jenkins for the past week with
500 runs. Not only this test is fixed but overall stability of entirely unit
tests are improved.
Please review @shralex @arshadmohammad
You can merge this pull request into a Git repository by running:
$ git pull https://github.com/hanm/zookeeper working
Alternatively you can review and apply these changes as the patch at:
https://github.com/apache/zookeeper/pull/315.patch
To close this pull request, make a commit to your master/trunk branch
with (at least) the following in the commit message:
This closes #315
----
commit f3b813924323a5fb64f9242303f3f5dd40d91a83
Author: Michael Han <[email protected]>
Date: 2017-07-23T06:03:46Z
ZOOKEEPER-2577: Fix flaky testDuringLeaderSync test caused by null config
file name.
----
> Flaky Test:
> org.apache.zookeeper.server.quorum.ReconfigDuringLeaderSyncTest.testDuringLeaderSync
> ------------------------------------------------------------------------------------------------
>
> Key: ZOOKEEPER-2577
> URL: https://issues.apache.org/jira/browse/ZOOKEEPER-2577
> Project: ZooKeeper
> Issue Type: Test
> Components: tests
> Affects Versions: 3.5.2
> Reporter: Michael Han
> Assignee: Mohammad Arshad
> Labels: flaky, flaky-test
> Fix For: 3.6.0
>
>
> {noformat}
> Error Message
> zoo.cfg.dynamic.next is not deleted.
> Stacktrace
> junit.framework.AssertionFailedError: zoo.cfg.dynamic.next is not deleted.
> at
> org.apache.zookeeper.server.quorum.ReconfigDuringLeaderSyncTest.testDuringLeaderSync(ReconfigDuringLeaderSyncTest.java:155)
> at
> org.apache.zookeeper.JUnit4ZKTestRunner$LoggedInvokeMethod.evaluate(JUnit4ZKTestRunner.java:79)
> Standard Output
> 2016-09-13 05:09:25,247 [myid:] - INFO [main:JUnit4ZKTestRunner@47] - No
> test.method specified. using default methods.
> 2016-09-13 05:09:25,349 [myid:] - INFO [main:JUnit4ZKTestRunner@47] - No
> test.method specified. using default methods.
> 2016-09-13 05:09:25,370 [myid:] - INFO [main:ZKTestCase$1@55] - STARTING
> testDuringLeaderSync
> 2016-09-13 05:09:25,372 [myid:] - INFO
> [main:JUnit4ZKTestRunner$LoggedInvokeMethod@77] - RUNNING TEST METHOD
> testDuringLeaderSync
> 2016-09-13 05:09:25,375 [myid:] - INFO [main:PortAssignment@151] - Test
> process 2/8 using ports from 13914 - 16606.
> 2016-09-13 05:09:25,380 [myid:] - INFO [main:PortAssignment@85] - Assigned
> port 13915 from range 13914 - 16606.
> 2016-09-13 05:09:25,380 [myid:] - INFO [main:PortAssignment@85] - Assigned
> port 13916 from range 13914 - 16606.
> 2016-09-13 05:09:25,381 [myid:] - INFO [main:PortAssignment@85] - Assigned
> port 13917 from range 13914 - 16606.
> 2016-09-13 05:09:25,381 [myid:] - INFO [main:PortAssignment@85] - Assigned
> port 13918 from range 13914 - 16606.
> 2016-09-13 05:09:25,381 [myid:] - INFO [main:PortAssignment@85] - Assigned
> port 13919 from range 13914 - 16606.
> 2016-09-13 05:09:25,382 [myid:] - INFO [main:PortAssignment@85] - Assigned
> port 13920 from range 13914 - 16606.
> 2016-09-13 05:09:25,382 [myid:] - INFO [main:PortAssignment@85] - Assigned
> port 13921 from range 13914 - 16606.
> 2016-09-13 05:09:25,382 [myid:] - INFO [main:PortAssignment@85] - Assigned
> port 13922 from range 13914 - 16606.
> 2016-09-13 05:09:25,383 [myid:] - INFO [main:PortAssignment@85] - Assigned
> port 13923 from range 13914 - 16606.
> 2016-09-13 05:09:25,406 [myid:] - INFO
> [main:QuorumPeerTestBase$MainThread@131] - id = 0 tmpDir =
> /home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/test/tmp/test8397079557861207505.junit.dir
> clientPort = 13915 adminServerPort = 8080
> 2016-09-13 05:09:25,416 [myid:] - INFO
> [main:QuorumPeerTestBase$MainThread@131] - id = 1 tmpDir =
> /home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/test/tmp/test1768888919429940621.junit.dir
> clientPort = 13918 adminServerPort = 8080
> 2016-09-13 05:09:25,420 [myid:] - INFO
> [main:QuorumPeerTestBase$MainThread@131] - id = 2 tmpDir =
> /home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/test/tmp/test5455612786130415623.junit.dir
> clientPort = 13921 adminServerPort = 8080
> 2016-09-13 05:09:25,422 [myid:] - INFO [Thread-0:QuorumPeerConfig@116] -
> Reading configuration from:
> /home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/test/tmp/test8397079557861207505.junit.dir/zoo.cfg
> 2016-09-13 05:09:25,422 [myid:] - INFO [Thread-2:QuorumPeerConfig@116] -
> Reading configuration from:
> /home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/test/tmp/test5455612786130415623.junit.dir/zoo.cfg
> 2016-09-13 05:09:25,422 [myid:] - INFO [Thread-1:QuorumPeerConfig@116] -
> Reading configuration from:
> /home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/test/tmp/test1768888919429940621.junit.dir/zoo.cfg
> 2016-09-13 05:09:25,424 [myid:] - INFO [main:FourLetterWordMain@85] -
> connecting to 127.0.0.1 13915
> 2016-09-13 05:09:25,425 [myid:] - INFO [Thread-0:QuorumPeerConfig@318] -
> clientPortAddress is 0.0.0.0/0.0.0.0:13915
> 2016-09-13 05:09:25,425 [myid:] - INFO [Thread-0:QuorumPeerConfig@322] -
> secureClientPort is not set
> 2016-09-13 05:09:25,425 [myid:] - INFO [Thread-1:QuorumPeerConfig@318] -
> clientPortAddress is 0.0.0.0/0.0.0.0:13918
> 2016-09-13 05:09:25,425 [myid:] - INFO [Thread-1:QuorumPeerConfig@322] -
> secureClientPort is not set
> 2016-09-13 05:09:25,425 [myid:] - INFO [Thread-2:QuorumPeerConfig@318] -
> clientPortAddress is 0.0.0.0/0.0.0.0:13921
> 2016-09-13 05:09:25,426 [myid:] - INFO [Thread-2:QuorumPeerConfig@322] -
> secureClientPort is not set
> 2016-09-13 05:09:25,430 [myid:] - INFO [main:ClientBase@248] - server
> 127.0.0.1:13915 not up
> java.net.ConnectException: Connection refused
> at java.net.PlainSocketImpl.socketConnect(Native Method)
> at
> java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:339)
> at
> java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:200)
> at
> java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:182)
> at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
> at java.net.Socket.connect(Socket.java:579)
> at
> org.apache.zookeeper.client.FourLetterWordMain.send4LetterWord(FourLetterWordMain.java:99)
> at
> org.apache.zookeeper.client.FourLetterWordMain.send4LetterWord(FourLetterWordMain.java:69)
> at
> org.apache.zookeeper.test.ClientBase.waitForServerUp(ClientBase.java:241)
> at
> org.apache.zookeeper.test.ClientBase.waitForServerUp(ClientBase.java:232)
> at
> org.apache.zookeeper.server.quorum.ReconfigDuringLeaderSyncTest.testDuringLeaderSync(ReconfigDuringLeaderSyncTest.java:85)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:606)
> at
> org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
> at
> org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
> at
> org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
> at
> org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
> at
> org.apache.zookeeper.JUnit4ZKTestRunner$LoggedInvokeMethod.evaluate(JUnit4ZKTestRunner.java:79)
> at
> org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
> at org.junit.rules.TestWatchman$1.evaluate(TestWatchman.java:53)
> at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
> at
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
> at
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
> at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
> at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
> at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
> at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
> at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
> at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
> at junit.framework.JUnit4TestAdapter.run(JUnit4TestAdapter.java:38)
> at
> org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.run(JUnitTestRunner.java:535)
> at
> org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.launch(JUnitTestRunner.java:1182)
> at
> org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.main(JUnitTestRunner.java:1033)
> 2016-09-13 05:09:25,444 [myid:1] - INFO [Thread-1:DatadirCleanupManager@78]
> - autopurge.snapRetainCount set to 3
> 2016-09-13 05:09:25,445 [myid:2] - INFO [Thread-2:DatadirCleanupManager@78]
> - autopurge.snapRetainCount set to 3
> 2016-09-13 05:09:25,445 [myid:2] - INFO [Thread-2:DatadirCleanupManager@79]
> - autopurge.purgeInterval set to 0
> 2016-09-13 05:09:25,444 [myid:0] - INFO [Thread-0:DatadirCleanupManager@78]
> - autopurge.snapRetainCount set to 3
> 2016-09-13 05:09:25,445 [myid:2] - INFO [Thread-2:DatadirCleanupManager@101]
> - Purge task is not scheduled.
> 2016-09-13 05:09:25,445 [myid:1] - INFO [Thread-1:DatadirCleanupManager@79]
> - autopurge.purgeInterval set to 0
> 2016-09-13 05:09:25,446 [myid:1] - INFO [Thread-1:DatadirCleanupManager@101]
> - Purge task is not scheduled.
> 2016-09-13 05:09:25,445 [myid:0] - INFO [Thread-0:DatadirCleanupManager@79]
> - autopurge.purgeInterval set to 0
> 2016-09-13 05:09:25,446 [myid:0] - INFO [Thread-0:DatadirCleanupManager@101]
> - Purge task is not scheduled.
> 2016-09-13 05:09:25,446 [myid:2] - INFO [Thread-2:ManagedUtil@46] - Log4j
> found with jmx enabled.
> 2016-09-13 05:09:25,447 [myid:0] - INFO [Thread-0:ManagedUtil@46] - Log4j
> found with jmx enabled.
> 2016-09-13 05:09:25,446 [myid:1] - INFO [Thread-1:ManagedUtil@46] - Log4j
> found with jmx enabled.
> 2016-09-13 05:09:25,552 [myid:1] - ERROR [Thread-1:ManagedUtil@114] -
> Problems while registering log4j jmx beans!
> javax.management.InstanceAlreadyExistsException: log4j:hiearchy=default
> at com.sun.jmx.mbeanserver.Repository.addMBean(Repository.java:437)
> at
> com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerWithRepository(DefaultMBeanServerInterceptor.java:1898)
> at
> com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerDynamicMBean(DefaultMBeanServerInterceptor.java:966)
> at
> com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerObject(DefaultMBeanServerInterceptor.java:900)
> at
> com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerMBean(DefaultMBeanServerInterceptor.java:324)
> at
> com.sun.jmx.mbeanserver.JmxMBeanServer.registerMBean(JmxMBeanServer.java:522)
> at
> org.apache.zookeeper.jmx.ManagedUtil.registerLog4jMBeans(ManagedUtil.java:75)
> at
> org.apache.zookeeper.server.quorum.QuorumPeerMain.runFromConfig(QuorumPeerMain.java:131)
> at
> org.apache.zookeeper.server.quorum.QuorumPeerMain.initializeAndRun(QuorumPeerMain.java:120)
> at
> org.apache.zookeeper.server.quorum.QuorumPeerTestBase$MainThread.run(QuorumPeerTestBase.java:245)
> at java.lang.Thread.run(Thread.java:745)
> 2016-09-13 05:09:25,552 [myid:1] - WARN [Thread-1:QuorumPeerMain@133] -
> Unable to register log4j JMX control
> javax.management.JMException:
> javax.management.InstanceAlreadyExistsException: log4j:hiearchy=default
> at
> org.apache.zookeeper.jmx.ManagedUtil.registerLog4jMBeans(ManagedUtil.java:115)
> at
> org.apache.zookeeper.server.quorum.QuorumPeerMain.runFromConfig(QuorumPeerMain.java:131)
> at
> org.apache.zookeeper.server.quorum.QuorumPeerMain.initializeAndRun(QuorumPeerMain.java:120)
> at
> org.apache.zookeeper.server.quorum.QuorumPeerTestBase$MainThread.run(QuorumPeerTestBase.java:245)
> at java.lang.Thread.run(Thread.java:745)
> 2016-09-13 05:09:25,553 [myid:1] - INFO [Thread-1:QuorumPeerMain@136] -
> Starting quorum peer
> 2016-09-13 05:09:25,553 [myid:2] - ERROR [Thread-2:HierarchyDynamicMBean@138]
> - Could not add loggerMBean for [root].
> javax.management.InstanceAlreadyExistsException: log4j:logger=root
> at com.sun.jmx.mbeanserver.Repository.addMBean(Repository.java:437)
> at
> com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerWithRepository(DefaultMBeanServerInterceptor.java:1898)
> at
> com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerDynamicMBean(DefaultMBeanServerInterceptor.java:966)
> at
> com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerObject(DefaultMBeanServerInterceptor.java:900)
> at
> com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerMBean(DefaultMBeanServerInterceptor.java:324)
> at
> com.sun.jmx.mbeanserver.JmxMBeanServer.registerMBean(JmxMBeanServer.java:522)
> at
> org.apache.log4j.jmx.AbstractDynamicMBean.registerMBean(AbstractDynamicMBean.java:160)
> at
> org.apache.log4j.jmx.HierarchyDynamicMBean.addLoggerMBean(HierarchyDynamicMBean.java:125)
> at
> org.apache.log4j.jmx.HierarchyDynamicMBean.postRegister(HierarchyDynamicMBean.java:263)
> at
> com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.postRegister(DefaultMBeanServerInterceptor.java:1024)
> at
> com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerDynamicMBean(DefaultMBeanServerInterceptor.java:974)
> at
> com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerObject(DefaultMBeanServerInterceptor.java:900)
> at
> com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerMBean(DefaultMBeanServerInterceptor.java:324)
> at
> com.sun.jmx.mbeanserver.JmxMBeanServer.registerMBean(JmxMBeanServer.java:522)
> at
> org.apache.zookeeper.jmx.ManagedUtil.registerLog4jMBeans(ManagedUtil.java:75)
> at
> org.apache.zookeeper.server.quorum.QuorumPeerMain.runFromConfig(QuorumPeerMain.java:131)
> at
> org.apache.zookeeper.server.quorum.QuorumPeerMain.initializeAndRun(QuorumPeerMain.java:120)
> at
> org.apache.zookeeper.server.quorum.QuorumPeerTestBase$MainThread.run(QuorumPeerTestBase.java:245)
> at java.lang.Thread.run(Thread.java:745)
> 2016-09-13 05:09:25,559 [myid:0] - ERROR [Thread-0:ManagedUtil@114] -
> Problems while registering log4j jmx beans!
> javax.management.InstanceAlreadyExistsException: log4j:hiearchy=default
> at com.sun.jmx.mbeanserver.Repository.addMBean(Repository.java:437)
> at
> com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerWithRepository(DefaultMBeanServerInterceptor.java:1898)
> at
> com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerDynamicMBean(DefaultMBeanServerInterceptor.java:966)
> at
> com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerObject(DefaultMBeanServerInterceptor.java:900)
> at
> com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerMBean(DefaultMBeanServerInterceptor.java:324)
> at
> com.sun.jmx.mbeanserver.JmxMBeanServer.registerMBean(JmxMBeanServer.java:522)
> at
> org.apache.zookeeper.jmx.ManagedUtil.registerLog4jMBeans(ManagedUtil.java:75)
> at
> org.apache.zookeeper.server.quorum.QuorumPeerMain.runFromConfig(QuorumPeerMain.java:131)
> at
> org.apache.zookeeper.server.quorum.QuorumPeerMain.initializeAndRun(QuorumPeerMain.java:120)
> at
> org.apache.zookeeper.server.quorum.QuorumPeerTestBase$MainThread.run(QuorumPeerTestBase.java:245)
> at java.lang.Thread.run(Thread.java:745)
> 2016-09-13 05:09:25,560 [myid:0] - WARN [Thread-0:QuorumPeerMain@133] -
> Unable to register log4j JMX control
> javax.management.JMException:
> javax.management.InstanceAlreadyExistsException: log4j:hiearchy=default
> at
> org.apache.zookeeper.jmx.ManagedUtil.registerLog4jMBeans(ManagedUtil.java:115)
> at
> org.apache.zookeeper.server.quorum.QuorumPeerMain.runFromConfig(QuorumPeerMain.java:131)
> at
> org.apache.zookeeper.server.quorum.QuorumPeerMain.initializeAndRun(QuorumPeerMain.java:120)
> at
> org.apache.zookeeper.server.quorum.QuorumPeerTestBase$MainThread.run(QuorumPeerTestBase.java:245)
> at java.lang.Thread.run(Thread.java:745)
> 2016-09-13 05:09:25,560 [myid:0] - INFO [Thread-0:QuorumPeerMain@136] -
> Starting quorum peer
> 2016-09-13 05:09:25,562 [myid:2] - INFO [Thread-2:QuorumPeerMain@136] -
> Starting quorum peer
> 2016-09-13 05:09:25,581 [myid:0] - INFO [Thread-0:NIOServerCnxnFactory@673]
> - Configuring NIO connection handler with 10s sessionless connection timeout,
> 1 selector thread(s), 8 worker threads, and 64 kB direct buffers.
> 2016-09-13 05:09:25,581 [myid:2] - INFO [Thread-2:NIOServerCnxnFactory@673]
> - Configuring NIO connection handler with 10s sessionless connection timeout,
> 1 selector thread(s), 8 worker threads, and 64 kB direct buffers.
> 2016-09-13 05:09:25,585 [myid:1] - INFO [Thread-1:NIOServerCnxnFactory@673]
> - Configuring NIO connection handler with 10s sessionless connection timeout,
> 1 selector thread(s), 8 worker threads, and 64 kB direct buffers.
> 2016-09-13 05:09:25,591 [myid:0] - INFO [Thread-0:NIOServerCnxnFactory@686]
> - binding to port /127.0.0.1:13915
> 2016-09-13 05:09:25,592 [myid:1] - INFO [Thread-1:NIOServerCnxnFactory@686]
> - binding to port /127.0.0.1:13918
> 2016-09-13 05:09:25,593 [myid:2] - INFO [Thread-2:NIOServerCnxnFactory@686]
> - binding to port /127.0.0.1:13921
> 2016-09-13 05:09:25,622 [myid:2] - INFO [Thread-2:QuorumPeer@1327] - Local
> sessions disabled
> 2016-09-13 05:09:25,622 [myid:2] - INFO [Thread-2:QuorumPeer@1338] - Local
> session upgrading disabled
> 2016-09-13 05:09:25,622 [myid:2] - INFO [Thread-2:QuorumPeer@1305] -
> tickTime set to 4000
> 2016-09-13 05:09:25,622 [myid:2] - INFO [Thread-2:QuorumPeer@1349] -
> minSessionTimeout set to 8000
> 2016-09-13 05:09:25,622 [myid:2] - INFO [Thread-2:QuorumPeer@1360] -
> maxSessionTimeout set to 80000
> 2016-09-13 05:09:25,622 [myid:1] - INFO [Thread-1:QuorumPeer@1327] - Local
> sessions disabled
> 2016-09-13 05:09:25,622 [myid:1] - INFO [Thread-1:QuorumPeer@1338] - Local
> session upgrading disabled
> 2016-09-13 05:09:25,623 [myid:1] - INFO [Thread-1:QuorumPeer@1305] -
> tickTime set to 4000
> 2016-09-13 05:09:25,623 [myid:1] - INFO [Thread-1:QuorumPeer@1349] -
> minSessionTimeout set to 8000
> 2016-09-13 05:09:25,623 [myid:1] - INFO [Thread-1:QuorumPeer@1360] -
> maxSessionTimeout set to 80000
> 2016-09-13 05:09:25,623 [myid:1] - INFO [Thread-1:QuorumPeer@1375] -
> initLimit set to 10
> 2016-09-13 05:09:25,622 [myid:0] - INFO [Thread-0:QuorumPeer@1327] - Local
> sessions disabled
> 2016-09-13 05:09:25,625 [myid:0] - INFO [Thread-0:QuorumPeer@1338] - Local
> session upgrading disabled
> 2016-09-13 05:09:25,625 [myid:0] - INFO [Thread-0:QuorumPeer@1305] -
> tickTime set to 4000
> 2016-09-13 05:09:25,625 [myid:0] - INFO [Thread-0:QuorumPeer@1349] -
> minSessionTimeout set to 8000
> 2016-09-13 05:09:25,625 [myid:0] - INFO [Thread-0:QuorumPeer@1360] -
> maxSessionTimeout set to 80000
> 2016-09-13 05:09:25,625 [myid:0] - INFO [Thread-0:QuorumPeer@1375] -
> initLimit set to 10
> 2016-09-13 05:09:25,622 [myid:2] - INFO [Thread-2:QuorumPeer@1375] -
> initLimit set to 10
> 2016-09-13 05:09:25,666 [myid:0] - INFO [Thread-0:QuorumPeer@776] -
> currentEpoch not found! Creating with a reasonable default of 0. This should
> only happen when you are upgrading your installation
> 2016-09-13 05:09:25,668 [myid:1] - INFO [Thread-1:QuorumPeer@776] -
> currentEpoch not found! Creating with a reasonable default of 0. This should
> only happen when you are upgrading your installation
> 2016-09-13 05:09:25,668 [myid:2] - INFO [Thread-2:QuorumPeer@776] -
> currentEpoch not found! Creating with a reasonable default of 0. This should
> only happen when you are upgrading your installation
> 2016-09-13 05:09:25,669 [myid:0] - INFO [Thread-0:QuorumPeer@791] -
> acceptedEpoch not found! Creating with a reasonable default of 0. This should
> only happen when you are upgrading your installation
> 2016-09-13 05:09:25,672 [myid:1] - INFO [Thread-1:QuorumPeer@791] -
> acceptedEpoch not found! Creating with a reasonable default of 0. This should
> only happen when you are upgrading your installation
> 2016-09-13 05:09:25,677 [myid:2] - INFO [Thread-2:QuorumPeer@791] -
> acceptedEpoch not found! Creating with a reasonable default of 0. This should
> only happen when you are upgrading your installation
> 2016-09-13 05:09:25,689 [myid:] - INFO [main:FourLetterWordMain@85] -
> connecting to 127.0.0.1 13915
> 2016-09-13 05:09:25,704 [myid:0] - INFO
> [NIOServerCxnFactory.AcceptThread:/127.0.0.1:13915:NIOServerCnxnFactory$AcceptThread@296]
> - Accepted socket connection from /127.0.0.1:38366
> 2016-09-13 05:09:25,758 [myid:0] - INFO
> [NIOWorkerThread-1:NIOServerCnxn@485] - Processing stat command from
> /127.0.0.1:38366
> 2016-09-13 05:09:25,770 [myid:1] - INFO
> [QuorumPeerListener:QuorumCnxManager$Listener@632] - My election bind port:
> /127.0.0.1:13920
> 2016-09-13 05:09:25,772 [myid:0] - INFO
> [NIOWorkerThread-1:NIOServerCnxn@607] - Closed socket connection for client
> /127.0.0.1:38366 (no session established for client)
> 2016-09-13 05:09:25,783 [myid:1] - INFO
> [QuorumPeer[myid=1](plain=/127.0.0.1:13918)(secure=disabled):QuorumPeer@1033]
> - LOOKING
> 2016-09-13 05:09:25,785 [myid:1] - INFO
> [QuorumPeer[myid=1](plain=/127.0.0.1:13918)(secure=disabled):FastLeaderElection@894]
> - New election. My id = 1, proposed zxid=0x0
> 2016-09-13 05:09:25,797 [myid:0] - INFO
> [QuorumPeerListener:QuorumCnxManager$Listener@632] - My election bind port:
> /127.0.0.1:13917
> 2016-09-13 05:09:25,798 [myid:0] - INFO
> [QuorumPeer[myid=0](plain=/127.0.0.1:13915)(secure=disabled):QuorumPeer@1033]
> - LOOKING
> 2016-09-13 05:09:25,798 [myid:0] - INFO
> [QuorumPeer[myid=0](plain=/127.0.0.1:13915)(secure=disabled):FastLeaderElection@894]
> - New election. My id = 0, proposed zxid=0x0
> 2016-09-13 05:09:25,799 [myid:0] - INFO
> [/127.0.0.1:13917:QuorumCnxManager$Listener@638] - Received connection
> request /127.0.0.1:53023
> 2016-09-13 05:09:25,806 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/127.0.0.1:13921)(secure=disabled):QuorumPeer@1033]
> - LOOKING
> 2016-09-13 05:09:25,806 [myid:2] - INFO
> [QuorumPeerListener:QuorumCnxManager$Listener@632] - My election bind port:
> /127.0.0.1:13923
> 2016-09-13 05:09:25,806 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/127.0.0.1:13921)(secure=disabled):FastLeaderElection@894]
> - New election. My id = 2, proposed zxid=0x0
> 2016-09-13 05:09:25,825 [myid:2] - INFO
> [/127.0.0.1:13923:QuorumCnxManager$Listener@638] - Received connection
> request /127.0.0.1:58679
> 2016-09-13 05:09:25,826 [myid:0] - INFO
> [WorkerSender[myid=0]:QuorumCnxManager@276] - Have smaller server identifier,
> so dropping the connection: (2, 0)
> 2016-09-13 05:09:25,825 [myid:1] - INFO
> [WorkerSender[myid=1]:QuorumCnxManager@276] - Have smaller server identifier,
> so dropping the connection: (2, 1)
> 2016-09-13 05:09:25,827 [myid:0] - INFO
> [/127.0.0.1:13917:QuorumCnxManager$Listener@638] - Received connection
> request /127.0.0.1:53026
> 2016-09-13 05:09:25,827 [myid:0] - INFO
> [WorkerReceiver[myid=0]:FastLeaderElection@688] - Notification: 2 (message
> format version), 0 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING
> (n.state), 0 (n.sid), 0x0 (n.peerEPoch), LOOKING (my state)0 (n.config
> version)
> 2016-09-13 05:09:25,827 [myid:1] - INFO
> [WorkerReceiver[myid=1]:FastLeaderElection@688] - Notification: 2 (message
> format version), 1 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING
> (n.state), 1 (n.sid), 0x0 (n.peerEPoch), LOOKING (my state)0 (n.config
> version)
> 2016-09-13 05:09:25,848 [myid:1] - INFO
> [/127.0.0.1:13920:QuorumCnxManager$Listener@638] - Received connection
> request /127.0.0.1:46423
> 2016-09-13 05:09:25,848 [myid:1] - INFO
> [WorkerReceiver[myid=1]:FastLeaderElection@688] - Notification: 2 (message
> format version), 0 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING
> (n.state), 0 (n.sid), 0x0 (n.peerEPoch), LOOKING (my state)0 (n.config
> version)
> 2016-09-13 05:09:25,857 [myid:2] - INFO
> [/127.0.0.1:13923:QuorumCnxManager$Listener@638] - Received connection
> request /127.0.0.1:58680
> 2016-09-13 05:09:25,857 [myid:0] - INFO
> [WorkerReceiver[myid=0]:FastLeaderElection@688] - Notification: 2 (message
> format version), 1 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING
> (n.state), 1 (n.sid), 0x0 (n.peerEPoch), LOOKING (my state)0 (n.config
> version)
> 2016-09-13 05:09:25,858 [myid:2] - WARN
> [RecvWorker:0:QuorumCnxManager$RecvWorker@915] - Connection broken for id 0,
> my id = 2, error =
> java.net.SocketException: Socket closed
> at java.net.SocketInputStream.socketRead0(Native Method)
> at java.net.SocketInputStream.read(SocketInputStream.java:152)
> at java.net.SocketInputStream.read(SocketInputStream.java:122)
> at java.net.SocketInputStream.read(SocketInputStream.java:210)
> at java.io.DataInputStream.readInt(DataInputStream.java:387)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager$RecvWorker.run(QuorumCnxManager.java:900)
> 2016-09-13 05:09:25,858 [myid:2] - WARN
> [RecvWorker:0:QuorumCnxManager$RecvWorker@918] - Interrupting SendWorker
> 2016-09-13 05:09:25,862 [myid:1] - INFO
> [WorkerReceiver[myid=1]:FastLeaderElection@688] - Notification: 2 (message
> format version), 1 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING
> (n.state), 0 (n.sid), 0x0 (n.peerEPoch), LOOKING (my state)0 (n.config
> version)
> 2016-09-13 05:09:25,863 [myid:0] - INFO
> [WorkerReceiver[myid=0]:FastLeaderElection@688] - Notification: 2 (message
> format version), 1 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING
> (n.state), 0 (n.sid), 0x0 (n.peerEPoch), LOOKING (my state)0 (n.config
> version)
> 2016-09-13 05:09:25,865 [myid:0] - WARN
> [SendWorker:2:QuorumCnxManager$SendWorker@837] - Exception when using
> channel: for id 2 my id = 0 error = java.net.SocketException: Broken pipe
> 2016-09-13 05:09:25,867 [myid:0] - WARN
> [RecvWorker:2:QuorumCnxManager$RecvWorker@918] - Interrupting SendWorker
> 2016-09-13 05:09:25,898 [myid:2] - WARN
> [SendWorker:0:QuorumCnxManager$SendWorker@832] - Interrupted while waiting
> for message on queue
> java.lang.InterruptedException
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2017)
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2095)
> at
> java.util.concurrent.ArrayBlockingQueue.poll(ArrayBlockingQueue.java:389)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.pollSendQueue(QuorumCnxManager.java:982)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.access$500(QuorumCnxManager.java:63)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager$SendWorker.run(QuorumCnxManager.java:820)
> 2016-09-13 05:09:25,898 [myid:1] - INFO
> [WorkerReceiver[myid=1]:FastLeaderElection@688] - Notification: 2 (message
> format version), 2 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING
> (n.state), 2 (n.sid), 0x0 (n.peerEPoch), LOOKING (my state)0 (n.config
> version)
> 2016-09-13 05:09:25,898 [myid:2] - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@688] - Notification: 2 (message
> format version), 2 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING
> (n.state), 2 (n.sid), 0x0 (n.peerEPoch), LOOKING (my state)0 (n.config
> version)
> 2016-09-13 05:09:25,899 [myid:0] - WARN
> [SendWorker:2:QuorumCnxManager$SendWorker@841] - Send worker leaving thread
> id 2 my id = 0
> 2016-09-13 05:09:25,899 [myid:2] - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@688] - Notification: 2 (message
> format version), 1 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING
> (n.state), 1 (n.sid), 0x0 (n.peerEPoch), LOOKING (my state)0 (n.config
> version)
> 2016-09-13 05:09:25,900 [myid:1] - INFO
> [WorkerReceiver[myid=1]:FastLeaderElection@688] - Notification: 2 (message
> format version), 2 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING
> (n.state), 1 (n.sid), 0x0 (n.peerEPoch), LOOKING (my state)0 (n.config
> version)
> 2016-09-13 05:09:25,901 [myid:0] - INFO
> [WorkerReceiver[myid=0]:FastLeaderElection@688] - Notification: 2 (message
> format version), 2 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING
> (n.state), 1 (n.sid), 0x0 (n.peerEPoch), LOOKING (my state)0 (n.config
> version)
> 2016-09-13 05:09:25,901 [myid:0] - INFO
> [/127.0.0.1:13917:QuorumCnxManager$Listener@638] - Received connection
> request /127.0.0.1:53028
> 2016-09-13 05:09:25,898 [myid:2] - WARN
> [SendWorker:0:QuorumCnxManager$SendWorker@841] - Send worker leaving thread
> id 0 my id = 2
> 2016-09-13 05:09:25,901 [myid:2] - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@688] - Notification: 2 (message
> format version), 2 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING
> (n.state), 1 (n.sid), 0x0 (n.peerEPoch), LOOKING (my state)0 (n.config
> version)
> 2016-09-13 05:09:25,902 [myid:0] - INFO
> [WorkerSender[myid=0]:QuorumCnxManager@276] - Have smaller server identifier,
> so dropping the connection: (2, 0)
> 2016-09-13 05:09:25,903 [myid:1] - INFO
> [WorkerReceiver[myid=1]:FastLeaderElection@688] - Notification: 2 (message
> format version), 2 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING
> (n.state), 0 (n.sid), 0x0 (n.peerEPoch), LOOKING (my state)0 (n.config
> version)
> 2016-09-13 05:09:25,903 [myid:0] - INFO
> [WorkerReceiver[myid=0]:FastLeaderElection@688] - Notification: 2 (message
> format version), 2 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING
> (n.state), 0 (n.sid), 0x0 (n.peerEPoch), LOOKING (my state)0 (n.config
> version)
> 2016-09-13 05:09:25,904 [myid:2] - INFO
> [/127.0.0.1:13923:QuorumCnxManager$Listener@638] - Received connection
> request /127.0.0.1:58684
> 2016-09-13 05:09:25,905 [myid:2] - WARN
> [SendWorker:0:QuorumCnxManager$SendWorker@832] - Interrupted while waiting
> for message on queue
> java.lang.InterruptedException
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2017)
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2095)
> at
> java.util.concurrent.ArrayBlockingQueue.poll(ArrayBlockingQueue.java:389)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.pollSendQueue(QuorumCnxManager.java:982)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.access$500(QuorumCnxManager.java:63)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager$SendWorker.run(QuorumCnxManager.java:820)
> 2016-09-13 05:09:25,905 [myid:2] - WARN
> [SendWorker:0:QuorumCnxManager$SendWorker@841] - Send worker leaving thread
> id 0 my id = 2
> 2016-09-13 05:09:25,905 [myid:2] - WARN
> [RecvWorker:0:QuorumCnxManager$RecvWorker@918] - Interrupting SendWorker
> 2016-09-13 05:09:25,907 [myid:0] - WARN
> [SendWorker:2:QuorumCnxManager$SendWorker@837] - Exception when using
> channel: for id 2 my id = 0 error = java.net.SocketException: Broken pipe
> 2016-09-13 05:09:25,907 [myid:0] - INFO
> [/127.0.0.1:13917:QuorumCnxManager$Listener@638] - Received connection
> request /127.0.0.1:53030
> 2016-09-13 05:09:25,908 [myid:0] - WARN
> [SendWorker:2:QuorumCnxManager$SendWorker@841] - Send worker leaving thread
> id 2 my id = 0
> 2016-09-13 05:09:25,908 [myid:0] - WARN
> [RecvWorker:2:QuorumCnxManager$RecvWorker@918] - Interrupting SendWorker
> 2016-09-13 05:09:25,909 [myid:2] - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@688] - Notification: 2 (message
> format version), 2 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING
> (n.state), 0 (n.sid), 0x0 (n.peerEPoch), LOOKING (my state)0 (n.config
> version)
> 2016-09-13 05:09:25,910 [myid:0] - INFO
> [WorkerReceiver[myid=0]:FastLeaderElection@688] - Notification: 2 (message
> format version), 2 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING
> (n.state), 2 (n.sid), 0x0 (n.peerEPoch), LOOKING (my state)0 (n.config
> version)
> 2016-09-13 05:09:26,022 [myid:] - INFO [main:FourLetterWordMain@85] -
> connecting to 127.0.0.1 13915
> 2016-09-13 05:09:26,023 [myid:0] - INFO
> [NIOServerCxnFactory.AcceptThread:/127.0.0.1:13915:NIOServerCnxnFactory$AcceptThread@296]
> - Accepted socket connection from /127.0.0.1:38382
> 2016-09-13 05:09:26,032 [myid:0] - INFO
> [NIOWorkerThread-2:NIOServerCnxn@485] - Processing stat command from
> /127.0.0.1:38382
> 2016-09-13 05:09:26,033 [myid:0] - INFO
> [NIOWorkerThread-2:NIOServerCnxn@607] - Closed socket connection for client
> /127.0.0.1:38382 (no session established for client)
> 2016-09-13 05:09:26,103 [myid:1] - INFO
> [QuorumPeer[myid=1](plain=/127.0.0.1:13918)(secure=disabled):MBeanRegistry@128]
> - Unregister MBean
> [org.apache.ZooKeeperService:name0=ReplicatedServer_id1,name1=replica.1,name2=LeaderElection]
> 2016-09-13 05:09:26,104 [myid:1] - INFO
> [QuorumPeer[myid=1](plain=/127.0.0.1:13918)(secure=disabled):QuorumPeer@1109]
> - FOLLOWING
> 2016-09-13 05:09:26,109 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/127.0.0.1:13921)(secure=disabled):MBeanRegistry@128]
> - Unregister MBean
> [org.apache.ZooKeeperService:name0=ReplicatedServer_id2,name1=replica.2,name2=LeaderElection]
> 2016-09-13 05:09:26,110 [myid:1] - INFO
> [QuorumPeer[myid=1](plain=/127.0.0.1:13918)(secure=disabled):Learner@88] -
> TCP NoDelay set to: true
> 2016-09-13 05:09:26,110 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/127.0.0.1:13921)(secure=disabled):QuorumPeer@1121]
> - LEADING
> 2016-09-13 05:09:26,111 [myid:0] - INFO
> [QuorumPeer[myid=0](plain=/127.0.0.1:13915)(secure=disabled):MBeanRegistry@128]
> - Unregister MBean
> [org.apache.ZooKeeperService:name0=ReplicatedServer_id0,name1=replica.0,name2=LeaderElection]
> 2016-09-13 05:09:26,111 [myid:0] - INFO
> [QuorumPeer[myid=0](plain=/127.0.0.1:13915)(secure=disabled):QuorumPeer@1109]
> - FOLLOWING
> 2016-09-13 05:09:26,113 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/127.0.0.1:13921)(secure=disabled):Leader@63] - TCP
> NoDelay set to: true
> 2016-09-13 05:09:26,113 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/127.0.0.1:13921)(secure=disabled):Leader@83] -
> zookeeper.leader.maxConcurrentSnapshots = 10
> 2016-09-13 05:09:26,113 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/127.0.0.1:13921)(secure=disabled):Leader@85] -
> zookeeper.leader.maxConcurrentSnapshotTimeout = 5
> 2016-09-13 05:09:26,122 [myid:0] - INFO
> [QuorumPeer[myid=0](plain=/127.0.0.1:13915)(secure=disabled):Environment@109]
> - Server environment:zookeeper.version=3.6.0-SNAPSHOT--1, built on 09/13/2016
> 05:08 GMT
> 2016-09-13 05:09:26,122 [myid:0] - INFO
> [QuorumPeer[myid=0](plain=/127.0.0.1:13915)(secure=disabled):Environment@109]
> - Server environment:host.name=jenkins-test-5f3
> 2016-09-13 05:09:26,123 [myid:0] - INFO
> [QuorumPeer[myid=0](plain=/127.0.0.1:13915)(secure=disabled):Environment@109]
> - Server environment:java.version=1.7.0_101
> 2016-09-13 05:09:26,123 [myid:0] - INFO
> [QuorumPeer[myid=0](plain=/127.0.0.1:13915)(secure=disabled):Environment@109]
> - Server environment:java.vendor=Oracle Corporation
> 2016-09-13 05:09:26,123 [myid:0] - INFO
> [QuorumPeer[myid=0](plain=/127.0.0.1:13915)(secure=disabled):Environment@109]
> - Server environment:java.home=/usr/lib/jvm/java-7-openjdk-amd64/jre
> 2016-09-13 05:09:26,123 [myid:0] - INFO
> [QuorumPeer[myid=0](plain=/127.0.0.1:13915)(secure=disabled):Environment@109]
> - Server
> environment:java.class.path=/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/test/classes:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/test/lib/antlr-2.7.7.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/test/lib/antlr4-runtime-4.5.1-1.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/test/lib/checkstyle-6.13.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/test/lib/commons-beanutils-1.9.2.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/test/lib/commons-cli-1.3.1.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/test/lib/commons-collections-3.2.2.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/test/lib/commons-lang3-3.4.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/test/lib/commons-logging-1.1.1.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/test/lib/guava-18.0.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/test/lib/hamcrest-core-1.3.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/test/lib/junit-4.12.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/test/lib/mockito-all-1.8.2.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/classes:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/src/java/lib/ivy-2.4.0.jar:/home/jenkins/tools/ant/latest/lib/ant.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/lib/commons-cli-1.2.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/lib/jackson-core-asl-1.9.11.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/lib/jackson-mapper-asl-1.9.11.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/lib/javacc.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/lib/javax.servlet-api-3.1.0.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/lib/jetty-http-9.2.18.v20160721.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/lib/jetty-io-9.2.18.v20160721.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/lib/jetty-security-9.2.18.v20160721.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/lib/jetty-server-9.2.18.v20160721.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/lib/jetty-servlet-9.2.18.v20160721.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/lib/jetty-util-9.2.18.v20160721.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/lib/jline-2.11.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/lib/log4j-1.2.17.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/lib/netty-3.10.5.Final.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/lib/slf4j-api-1.7.5.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/lib/slf4j-log4j12-1.7.5.jar:/usr/local/asfpackages/ant/apache-ant-1.9.7/lib/ant-launcher.jar:/home/jenkins/tools/ant/latest/lib/ant-junit.jar:/home/jenkins/tools/ant/latest/lib/ant-junit4.jar
> 2016-09-13 05:09:26,123 [myid:0] - INFO
> [QuorumPeer[myid=0](plain=/127.0.0.1:13915)(secure=disabled):Environment@109]
> - Server
> environment:java.library.path=/usr/java/packages/lib/amd64:/usr/lib/x86_64-linux-gnu/jni:/lib/x86_64-linux-gnu:/usr/lib/x86_64-linux-gnu:/usr/lib/jni:/lib:/usr/lib
> 2016-09-13 05:09:26,123 [myid:0] - INFO
> [QuorumPeer[myid=0](plain=/127.0.0.1:13915)(secure=disabled):Environment@109]
> - Server environment:java.io.tmpdir=/tmp
> 2016-09-13 05:09:26,124 [myid:0] - INFO
> [QuorumPeer[myid=0](plain=/127.0.0.1:13915)(secure=disabled):Environment@109]
> - Server environment:java.compiler=<NA>
> 2016-09-13 05:09:26,124 [myid:0] - INFO
> [QuorumPeer[myid=0](plain=/127.0.0.1:13915)(secure=disabled):Environment@109]
> - Server environment:os.name=Linux
> 2016-09-13 05:09:26,124 [myid:0] - INFO
> [QuorumPeer[myid=0](plain=/127.0.0.1:13915)(secure=disabled):Environment@109]
> - Server environment:os.arch=amd64
> 2016-09-13 05:09:26,124 [myid:0] - INFO
> [QuorumPeer[myid=0](plain=/127.0.0.1:13915)(secure=disabled):Environment@109]
> - Server environment:os.version=3.13.0-30-generic
> 2016-09-13 05:09:26,124 [myid:0] - INFO
> [QuorumPeer[myid=0](plain=/127.0.0.1:13915)(secure=disabled):Environment@109]
> - Server environment:user.name=jenkins
> 2016-09-13 05:09:26,124 [myid:0] - INFO
> [QuorumPeer[myid=0](plain=/127.0.0.1:13915)(secure=disabled):Environment@109]
> - Server environment:user.home=/home/jenkins
> 2016-09-13 05:09:26,124 [myid:0] - INFO
> [QuorumPeer[myid=0](plain=/127.0.0.1:13915)(secure=disabled):Environment@109]
> - Server
> environment:user.dir=/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/test
> 2016-09-13 05:09:26,125 [myid:0] - INFO
> [QuorumPeer[myid=0](plain=/127.0.0.1:13915)(secure=disabled):Environment@109]
> - Server environment:os.memory.free=49MB
> 2016-09-13 05:09:26,125 [myid:0] - INFO
> [QuorumPeer[myid=0](plain=/127.0.0.1:13915)(secure=disabled):Environment@109]
> - Server environment:os.memory.max=455MB
> 2016-09-13 05:09:26,125 [myid:0] - INFO
> [QuorumPeer[myid=0](plain=/127.0.0.1:13915)(secure=disabled):Environment@109]
> - Server environment:os.memory.total=60MB
> 2016-09-13 05:09:26,126 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/127.0.0.1:13921)(secure=disabled):ZooKeeperServer@889]
> - minSessionTimeout set to 8000
> 2016-09-13 05:09:26,127 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/127.0.0.1:13921)(secure=disabled):ZooKeeperServer@898]
> - maxSessionTimeout set to 80000
> 2016-09-13 05:09:26,127 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/127.0.0.1:13921)(secure=disabled):ZooKeeperServer@159]
> - Created server with tickTime 4000 minSessionTimeout 8000 maxSessionTimeout
> 80000 datadir
> /home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/test/tmp/test5455612786130415623.junit.dir/data/version-2
> snapdir
> /home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/test/tmp/test5455612786130415623.junit.dir/data/version-2
> 2016-09-13 05:09:26,126 [myid:0] - INFO
> [QuorumPeer[myid=0](plain=/127.0.0.1:13915)(secure=disabled):ZooKeeperServer@889]
> - minSessionTimeout set to 8000
> 2016-09-13 05:09:26,129 [myid:0] - INFO
> [QuorumPeer[myid=0](plain=/127.0.0.1:13915)(secure=disabled):ZooKeeperServer@898]
> - maxSessionTimeout set to 80000
> 2016-09-13 05:09:26,129 [myid:0] - INFO
> [QuorumPeer[myid=0](plain=/127.0.0.1:13915)(secure=disabled):ZooKeeperServer@159]
> - Created server with tickTime 4000 minSessionTimeout 8000 maxSessionTimeout
> 80000 datadir
> /home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/test/tmp/test8397079557861207505.junit.dir/data/version-2
> snapdir
> /home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/test/tmp/test8397079557861207505.junit.dir/data/version-2
> 2016-09-13 05:09:26,129 [myid:0] - INFO
> [QuorumPeer[myid=0](plain=/127.0.0.1:13915)(secure=disabled):Follower@66] -
> FOLLOWING - LEADER ELECTION TOOK - 18 MS
> 2016-09-13 05:09:26,126 [myid:1] - INFO
> [QuorumPeer[myid=1](plain=/127.0.0.1:13918)(secure=disabled):ZooKeeperServer@889]
> - minSessionTimeout set to 8000
> 2016-09-13 05:09:26,129 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/127.0.0.1:13921)(secure=disabled):Leader@412] -
> LEADING - LEADER ELECTION TOOK - 20 MS
> 2016-09-13 05:09:26,140 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/127.0.0.1:13921)(secure=disabled):FileTxnSnapLog@298]
> - Snapshotting: 0x0 to
> /home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/test/tmp/test5455612786130415623.junit.dir/data/version-2/snapshot.0
> 2016-09-13 05:09:26,137 [myid:1] - INFO
> [QuorumPeer[myid=1](plain=/127.0.0.1:13918)(secure=disabled):ZooKeeperServer@898]
> - maxSessionTimeout set to 80000
> 2016-09-13 05:09:26,141 [myid:1] - INFO
> [QuorumPeer[myid=1](plain=/127.0.0.1:13918)(secure=disabled):ZooKeeperServer@159]
> - Created server with tickTime 4000 minSessionTimeout 8000 maxSessionTimeout
> 80000 datadir
> /home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/test/tmp/test1768888919429940621.junit.dir/data/version-2
> snapdir
> /home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/test/tmp/test1768888919429940621.junit.dir/data/version-2
> 2016-09-13 05:09:26,141 [myid:1] - INFO
> [QuorumPeer[myid=1](plain=/127.0.0.1:13918)(secure=disabled):Follower@66] -
> FOLLOWING - LEADER ELECTION TOOK - 37 MS
> 2016-09-13 05:09:26,185 [myid:2] - INFO
> [LearnerHandler-/127.0.0.1:39078:LearnerHandler@382] - Follower sid: 0 : info
> : 127.0.0.1:13916:13917:participant;127.0.0.1:13915
> 2016-09-13 05:09:26,191 [myid:2] - INFO
> [LearnerHandler-/127.0.0.1:39079:LearnerHandler@382] - Follower sid: 1 : info
> : 127.0.0.1:13919:13920:participant;127.0.0.1:13918
> 2016-09-13 05:09:26,198 [myid:2] - INFO
> [LearnerHandler-/127.0.0.1:39079:LearnerHandler@683] - Synchronizing with
> Follower sid: 1 maxCommittedLog=0x0 minCommittedLog=0x0 lastProcessedZxid=0x0
> peerLastZxid=0x0
> 2016-09-13 05:09:26,198 [myid:2] - INFO
> [LearnerHandler-/127.0.0.1:39079:LearnerHandler@727] - Sending DIFF zxid=0x0
> for peer sid: 1
> 2016-09-13 05:09:26,198 [myid:2] - INFO
> [LearnerHandler-/127.0.0.1:39078:LearnerHandler@683] - Synchronizing with
> Follower sid: 0 maxCommittedLog=0x0 minCommittedLog=0x0 lastProcessedZxid=0x0
> peerLastZxid=0x0
> 2016-09-13 05:09:26,199 [myid:2] - INFO
> [LearnerHandler-/127.0.0.1:39078:LearnerHandler@727] - Sending DIFF zxid=0x0
> for peer sid: 0
> 2016-09-13 05:09:26,201 [myid:1] - INFO
> [QuorumPeer[myid=1](plain=/127.0.0.1:13918)(secure=disabled):Learner@366] -
> Getting a diff from the leader 0x0
> 2016-09-13 05:09:26,206 [myid:1] - INFO
> [QuorumPeer[myid=1](plain=/127.0.0.1:13918)(secure=disabled):Learner@509] -
> Learner received NEWLEADER message
> 2016-09-13 05:09:26,209 [myid:1] - INFO
> [QuorumPeer[myid=1](plain=/127.0.0.1:13918)(secure=disabled):FileTxnSnapLog@298]
> - Snapshotting: 0x0 to
> /home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/test/tmp/test1768888919429940621.junit.dir/data/version-2/snapshot.0
> 2016-09-13 05:09:26,210 [myid:0] - INFO
> [QuorumPeer[myid=0](plain=/127.0.0.1:13915)(secure=disabled):Learner@366] -
> Getting a diff from the leader 0x0
> 2016-09-13 05:09:26,211 [myid:0] - INFO
> [QuorumPeer[myid=0](plain=/127.0.0.1:13915)(secure=disabled):Learner@509] -
> Learner received NEWLEADER message
> 2016-09-13 05:09:26,213 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/127.0.0.1:13921)(secure=disabled):Leader@1255] -
> Have quorum of supporters, sids: [ [1, 2],[1, 2] ]; starting up and setting
> last processed zxid: 0x100000000
> 2016-09-13 05:09:26,215 [myid:0] - INFO
> [QuorumPeer[myid=0](plain=/127.0.0.1:13915)(secure=disabled):FileTxnSnapLog@298]
> - Snapshotting: 0x0 to
> /home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/test/tmp/test8397079557861207505.junit.dir/data/version-2/snapshot.0
> 2016-09-13 05:09:26,238 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/127.0.0.1:13921)(secure=disabled):CommitProcessor@318]
> - Configuring CommitProcessor with 4 worker threads.
> 2016-09-13 05:09:26,252 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/127.0.0.1:13921)(secure=disabled):ContainerManager@64]
> - Using checkIntervalMs=60000 maxPerMinute=10000
> 2016-09-13 05:09:26,254 [myid:0] - INFO
> [QuorumPeer[myid=0](plain=/127.0.0.1:13915)(secure=disabled):Learner@493] -
> Learner received UPTODATE message
> 2016-09-13 05:09:26,254 [myid:1] - INFO
> [QuorumPeer[myid=1](plain=/127.0.0.1:13918)(secure=disabled):Learner@493] -
> Learner received UPTODATE message
> 2016-09-13 05:09:26,266 [myid:1] - INFO
> [QuorumPeer[myid=1](plain=/127.0.0.1:13918)(secure=disabled):CommitProcessor@318]
> - Configuring CommitProcessor with 4 worker threads.
> 2016-09-13 05:09:26,272 [myid:0] - INFO
> [QuorumPeer[myid=0](plain=/127.0.0.1:13915)(secure=disabled):CommitProcessor@318]
> - Configuring CommitProcessor with 4 worker threads.
> 2016-09-13 05:09:26,283 [myid:] - INFO [main:FourLetterWordMain@85] -
> connecting to 127.0.0.1 13915
> 2016-09-13 05:09:26,284 [myid:0] - INFO
> [NIOServerCxnFactory.AcceptThread:/127.0.0.1:13915:NIOServerCnxnFactory$AcceptThread@296]
> - Accepted socket connection from /127.0.0.1:38385
> 2016-09-13 05:09:26,285 [myid:0] - INFO
> [NIOWorkerThread-3:NIOServerCnxn@485] - Processing stat command from
> /127.0.0.1:38385
> 2016-09-13 05:09:26,286 [myid:0] - INFO [NIOWorkerThread-3:StatCommand@49] -
> Stat command output
> 2016-09-13 05:09:26,287 [myid:0] - INFO
> [NIOWorkerThread-3:NIOServerCnxn@607] - Closed socket connection for client
> /127.0.0.1:38385 (no session established for client)
> 2016-09-13 05:09:26,288 [myid:] - INFO [main:FourLetterWordMain@85] -
> connecting to 127.0.0.1 13918
> 2016-09-13 05:09:26,288 [myid:1] - INFO
> [NIOServerCxnFactory.AcceptThread:/127.0.0.1:13918:NIOServerCnxnFactory$AcceptThread@296]
> - Accepted socket connection from /127.0.0.1:55309
> 2016-09-13 05:09:26,291 [myid:1] - INFO
> [NIOWorkerThread-1:NIOServerCnxn@485] - Processing stat command from
> /127.0.0.1:55309
> 2016-09-13 05:09:26,291 [myid:1] - INFO [NIOWorkerThread-1:StatCommand@49] -
> Stat command output
> 2016-09-13 05:09:26,292 [myid:1] - INFO
> [NIOWorkerThread-1:NIOServerCnxn@607] - Closed socket connection for client
> /127.0.0.1:55309 (no session established for client)
> 2016-09-13 05:09:26,292 [myid:] - INFO [main:FourLetterWordMain@85] -
> connecting to 127.0.0.1 13921
> 2016-09-13 05:09:26,293 [myid:2] - INFO
> [NIOServerCxnFactory.AcceptThread:/127.0.0.1:13921:NIOServerCnxnFactory$AcceptThread@296]
> - Accepted socket connection from /127.0.0.1:45002
> 2016-09-13 05:09:26,297 [myid:2] - INFO
> [NIOWorkerThread-1:NIOServerCnxn@485] - Processing stat command from
> /127.0.0.1:45002
> 2016-09-13 05:09:26,297 [myid:2] - INFO [NIOWorkerThread-1:StatCommand@49] -
> Stat command output
> 2016-09-13 05:09:26,298 [myid:2] - INFO
> [NIOWorkerThread-1:NIOServerCnxn@607] - Closed socket connection for client
> /127.0.0.1:45002 (no session established for client)
> 2016-09-13 05:09:26,304 [myid:] - INFO [main:Environment@109] - Client
> environment:zookeeper.version=3.6.0-SNAPSHOT--1, built on 09/13/2016 05:08 GMT
> 2016-09-13 05:09:26,304 [myid:] - INFO [main:Environment@109] - Client
> environment:host.name=jenkins-test-5f3
> 2016-09-13 05:09:26,304 [myid:] - INFO [main:Environment@109] - Client
> environment:java.version=1.7.0_101
> 2016-09-13 05:09:26,305 [myid:] - INFO [main:Environment@109] - Client
> environment:java.vendor=Oracle Corporation
> 2016-09-13 05:09:26,305 [myid:] - INFO [main:Environment@109] - Client
> environment:java.home=/usr/lib/jvm/java-7-openjdk-amd64/jre
> 2016-09-13 05:09:26,305 [myid:] - INFO [main:Environment@109] - Client
> environment:java.class.path=/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/test/classes:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/test/lib/antlr-2.7.7.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/test/lib/antlr4-runtime-4.5.1-1.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/test/lib/checkstyle-6.13.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/test/lib/commons-beanutils-1.9.2.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/test/lib/commons-cli-1.3.1.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/test/lib/commons-collections-3.2.2.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/test/lib/commons-lang3-3.4.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/test/lib/commons-logging-1.1.1.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/test/lib/guava-18.0.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/test/lib/hamcrest-core-1.3.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/test/lib/junit-4.12.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/test/lib/mockito-all-1.8.2.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/classes:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/src/java/lib/ivy-2.4.0.jar:/home/jenkins/tools/ant/latest/lib/ant.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/lib/commons-cli-1.2.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/lib/jackson-core-asl-1.9.11.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/lib/jackson-mapper-asl-1.9.11.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/lib/javacc.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/lib/javax.servlet-api-3.1.0.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/lib/jetty-http-9.2.18.v20160721.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/lib/jetty-io-9.2.18.v20160721.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/lib/jetty-security-9.2.18.v20160721.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/lib/jetty-server-9.2.18.v20160721.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/lib/jetty-servlet-9.2.18.v20160721.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/lib/jetty-util-9.2.18.v20160721.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/lib/jline-2.11.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/lib/log4j-1.2.17.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/lib/netty-3.10.5.Final.
> ...[truncated 31909 chars]...
> 3] - WARN [RecvWorker:1:QuorumCnxManager$RecvWorker@915] - Connection broken
> for id 1, my id = 3, error =
> java.io.EOFException
> at java.io.DataInputStream.readInt(DataInputStream.java:392)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager$RecvWorker.run(QuorumCnxManager.java:900)
> 2016-09-13 05:09:26,894 [myid:3] - WARN
> [RecvWorker:1:QuorumCnxManager$RecvWorker@918] - Interrupting SendWorker
> 2016-09-13 05:09:26,894 [myid:3] - WARN
> [SendWorker:1:QuorumCnxManager$SendWorker@832] - Interrupted while waiting
> for message on queue
> java.lang.InterruptedException
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2017)
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2095)
> at
> java.util.concurrent.ArrayBlockingQueue.poll(ArrayBlockingQueue.java:389)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.pollSendQueue(QuorumCnxManager.java:982)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.access$500(QuorumCnxManager.java:63)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager$SendWorker.run(QuorumCnxManager.java:820)
> 2016-09-13 05:09:26,894 [myid:3] - WARN
> [SendWorker:1:QuorumCnxManager$SendWorker@841] - Send worker leaving thread
> id 1 my id = 3
> 2016-09-13 05:09:26,895 [myid:1] - WARN
> [RecvWorker:3:QuorumCnxManager$RecvWorker@915] - Connection broken for id 3,
> my id = 1, error =
> java.net.SocketException: Socket closed
> at java.net.SocketInputStream.socketRead0(Native Method)
> at java.net.SocketInputStream.read(SocketInputStream.java:152)
> at java.net.SocketInputStream.read(SocketInputStream.java:122)
> at java.net.SocketInputStream.read(SocketInputStream.java:210)
> at java.io.DataInputStream.readInt(DataInputStream.java:387)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager$RecvWorker.run(QuorumCnxManager.java:900)
> 2016-09-13 05:09:26,895 [myid:1] - WARN
> [RecvWorker:3:QuorumCnxManager$RecvWorker@918] - Interrupting SendWorker
> 2016-09-13 05:09:26,895 [myid:1] - WARN
> [SendWorker:3:QuorumCnxManager$SendWorker@832] - Interrupted while waiting
> for message on queue
> java.lang.InterruptedException
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2017)
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2095)
> at
> java.util.concurrent.ArrayBlockingQueue.poll(ArrayBlockingQueue.java:389)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.pollSendQueue(QuorumCnxManager.java:982)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.access$500(QuorumCnxManager.java:63)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager$SendWorker.run(QuorumCnxManager.java:820)
> 2016-09-13 05:09:26,896 [myid:1] - WARN
> [SendWorker:3:QuorumCnxManager$SendWorker@841] - Send worker leaving thread
> id 3 my id = 1
> 2016-09-13 05:09:26,905 [myid:0] - WARN
> [SendWorker:1:QuorumCnxManager$SendWorker@841] - Send worker leaving thread
> id 1 my id = 0
> 2016-09-13 05:09:26,905 [myid:0] - WARN
> [RecvWorker:3:QuorumCnxManager$RecvWorker@915] - Connection broken for id 3,
> my id = 0, error =
> java.net.SocketException: Socket closed
> at java.net.SocketInputStream.socketRead0(Native Method)
> at java.net.SocketInputStream.read(SocketInputStream.java:152)
> at java.net.SocketInputStream.read(SocketInputStream.java:122)
> at java.net.SocketInputStream.read(SocketInputStream.java:210)
> at java.io.DataInputStream.readInt(DataInputStream.java:387)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager$RecvWorker.run(QuorumCnxManager.java:900)
> 2016-09-13 05:09:26,906 [myid:0] - WARN
> [RecvWorker:3:QuorumCnxManager$RecvWorker@918] - Interrupting SendWorker
> 2016-09-13 05:09:26,905 [myid:3] - WARN
> [RecvWorker:0:QuorumCnxManager$RecvWorker@915] - Connection broken for id 0,
> my id = 3, error =
> java.io.EOFException
> at java.io.DataInputStream.readInt(DataInputStream.java:392)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager$RecvWorker.run(QuorumCnxManager.java:900)
> 2016-09-13 05:09:26,906 [myid:3] - WARN
> [RecvWorker:0:QuorumCnxManager$RecvWorker@918] - Interrupting SendWorker
> 2016-09-13 05:09:26,905 [myid:0] - WARN
> [SendWorker:3:QuorumCnxManager$SendWorker@832] - Interrupted while waiting
> for message on queue
> java.lang.InterruptedException
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2017)
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2095)
> at
> java.util.concurrent.ArrayBlockingQueue.poll(ArrayBlockingQueue.java:389)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.pollSendQueue(QuorumCnxManager.java:982)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.access$500(QuorumCnxManager.java:63)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager$SendWorker.run(QuorumCnxManager.java:820)
> 2016-09-13 05:09:26,913 [myid:3] - WARN
> [QuorumPeer[myid=3](plain=/0:0:0:0:0:0:0:0:13924)(secure=disabled):Learner@417]
> - Got zxid 0x100000002 expected 0x1
> 2016-09-13 05:09:26,917 [myid:3] - WARN
> [SendWorker:0:QuorumCnxManager$SendWorker@832] - Interrupted while waiting
> for message on queue
> java.lang.InterruptedException
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2017)
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2095)
> at
> java.util.concurrent.ArrayBlockingQueue.poll(ArrayBlockingQueue.java:389)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.pollSendQueue(QuorumCnxManager.java:982)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.access$500(QuorumCnxManager.java:63)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager$SendWorker.run(QuorumCnxManager.java:820)
> 2016-09-13 05:09:26,918 [myid:3] - WARN
> [SendWorker:0:QuorumCnxManager$SendWorker@841] - Send worker leaving thread
> id 0 my id = 3
> 2016-09-13 05:09:26,917 [myid:0] - WARN
> [SendWorker:3:QuorumCnxManager$SendWorker@841] - Send worker leaving thread
> id 3 my id = 0
> 2016-09-13 05:09:26,917 [myid:1] - INFO
> [QuorumPeerListener:QuorumCnxManager$Listener@632] - My election bind port:
> /127.0.0.1:13920
> 2016-09-13 05:09:26,919 [myid:3] - INFO
> [QuorumPeer[myid=3](plain=/0:0:0:0:0:0:0:0:13924)(secure=disabled):QuorumPeer@1481]
> - writeToDisk == true but configFilename == null
> 2016-09-13 05:09:26,920 [myid:3] - WARN
> [QuorumPeer[myid=3](plain=/0:0:0:0:0:0:0:0:13924)(secure=disabled):QuorumPeer@1417]
> - Restarting Leader Election
> 2016-09-13 05:09:26,920 [myid:3] - INFO
> [/127.0.0.1:13926:QuorumCnxManager$Listener@661] - Leaving listener
> 2016-09-13 05:09:26,922 [myid:0] - INFO
> [QuorumPeerListener:QuorumCnxManager$Listener@632] - My election bind port:
> /127.0.0.1:13917
> 2016-09-13 05:09:26,936 [myid:3] - INFO
> [QuorumPeer[myid=3](plain=/0:0:0:0:0:0:0:0:13924)(secure=disabled):Learner@493]
> - Learner received UPTODATE message
> 2016-09-13 05:09:26,936 [myid:3] - INFO
> [QuorumPeerListener:QuorumCnxManager$Listener@632] - My election bind port:
> /127.0.0.1:13926
> 2016-09-13 05:09:27,036 [myid:3] - INFO
> [QuorumPeer[myid=3](plain=/0:0:0:0:0:0:0:0:13924)(secure=disabled):CommitProcessor@318]
> - Configuring CommitProcessor with 4 worker threads.
> 2016-09-13 05:09:27,061 [myid:3] - INFO [SyncThread:3:FileTxnLog@204] -
> Creating new log file: log.100000002
> 2016-09-13 05:09:28,635 [myid:127.0.0.1:13924] - INFO
> [main-SendThread(127.0.0.1:13924):ClientCnxn$SendThread@1113] - Opening
> socket connection to server 127.0.0.1/127.0.0.1:13924. Will not attempt to
> authenticate using SASL (unknown error)
> 2016-09-13 05:09:28,635 [myid:127.0.0.1:13924] - INFO
> [main-SendThread(127.0.0.1:13924):ClientCnxn$SendThread@948] - Socket
> connection established, initiating session, client: /127.0.0.1:50397, server:
> 127.0.0.1/127.0.0.1:13924
> 2016-09-13 05:09:28,636 [myid:3] - INFO
> [NIOServerCxnFactory.AcceptThread:0.0.0.0/0.0.0.0:13924:NIOServerCnxnFactory$AcceptThread@296]
> - Accepted socket connection from /127.0.0.1:50397
> 2016-09-13 05:09:28,651 [myid:3] - INFO
> [NIOWorkerThread-2:ZooKeeperServer@995] - Client attempting to establish new
> session at /127.0.0.1:50397
> 2016-09-13 05:09:28,652 [myid:3] - WARN
> [QuorumPeer[myid=3](plain=/0:0:0:0:0:0:0:0:13924)(secure=disabled):Follower@122]
> - Got zxid 0x100000003 expected 0x1
> 2016-09-13 05:09:28,654 [myid:3] - INFO
> [CommitProcWorkThread-1:ZooKeeperServer@709] - Established session
> 0x3000048422c0000 with negotiated timeout 30000 for client /127.0.0.1:50397
> 2016-09-13 05:09:28,661 [myid:127.0.0.1:13924] - INFO
> [main-SendThread(127.0.0.1:13924):ClientCnxn$SendThread@1381] - Session
> establishment complete on server 127.0.0.1/127.0.0.1:13924, sessionid =
> 0x3000048422c0000, negotiated timeout = 30000
> 2016-09-13 05:09:28,690 [myid:] - INFO
> [main:JUnit4ZKTestRunner$LoggedInvokeMethod@98] - TEST METHOD FAILED
> testDuringLeaderSync
> java.lang.AssertionError: zoo.cfg.dynamic.next is not deleted.
> at org.junit.Assert.fail(Assert.java:88)
> at org.junit.Assert.assertTrue(Assert.java:41)
> at org.junit.Assert.assertFalse(Assert.java:64)
> at
> org.apache.zookeeper.server.quorum.ReconfigDuringLeaderSyncTest.testDuringLeaderSync(ReconfigDuringLeaderSyncTest.java:155)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:606)
> at
> org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
> at
> org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
> at
> org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
> at
> org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
> at
> org.apache.zookeeper.JUnit4ZKTestRunner$LoggedInvokeMethod.evaluate(JUnit4ZKTestRunner.java:79)
> at
> org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
> at org.junit.rules.TestWatchman$1.evaluate(TestWatchman.java:53)
> at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
> at
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
> at
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
> at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
> at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
> at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
> at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
> at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
> at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
> at junit.framework.JUnit4TestAdapter.run(JUnit4TestAdapter.java:38)
> at
> org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.run(JUnitTestRunner.java:535)
> at
> org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.launch(JUnitTestRunner.java:1182)
> at
> org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.main(JUnitTestRunner.java:1033)
> 2016-09-13 05:09:28,692 [myid:] - INFO [main:QuorumBase@394] - Shutting down
> quorum peer QuorumPeer[myid=0](plain=/127.0.0.1:13915)(secure=disabled)
> 2016-09-13 05:09:28,692 [myid:] - INFO [main:Follower@198] - shutdown called
> java.lang.Exception: shutdown Follower
> at
> org.apache.zookeeper.server.quorum.Follower.shutdown(Follower.java:198)
> at
> org.apache.zookeeper.server.quorum.QuorumPeer.shutdown(QuorumPeer.java:1184)
> at org.apache.zookeeper.test.QuorumBase.shutdown(QuorumBase.java:395)
> at
> org.apache.zookeeper.server.quorum.QuorumPeerTestBase$TestQPMain.shutdown(QuorumPeerTestBase.java:60)
> at
> org.apache.zookeeper.server.quorum.QuorumPeerTestBase$MainThread.shutdown(QuorumPeerTestBase.java:257)
> at
> org.apache.zookeeper.server.quorum.ReconfigDuringLeaderSyncTest.tearDown(ReconfigDuringLeaderSyncTest.java:189)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:606)
> at
> org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
> at
> org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
> at
> org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
> at
> org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:33)
> at org.junit.rules.TestWatchman$1.evaluate(TestWatchman.java:53)
> at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
> at
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
> at
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
> at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
> at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
> at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
> at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
> at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
> at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
> at junit.framework.JUnit4TestAdapter.run(JUnit4TestAdapter.java:38)
> at
> org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.run(JUnitTestRunner.java:535)
> at
> org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.launch(JUnitTestRunner.java:1182)
> at
> org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.main(JUnitTestRunner.java:1033)
> 2016-09-13 05:09:28,693 [myid:] - INFO [main:MBeanRegistry@128] - Unregister
> MBean
> [org.apache.ZooKeeperService:name0=ReplicatedServer_id0,name1=replica.0,name2=Follower,name3=Connections,name4=127.0.0.1,name5=0x483fd50000]
> 2016-09-13 05:09:28,694 [myid:] - INFO [main:NIOServerCnxn@607] - Closed
> socket connection for client /127.0.0.1:38389 which had sessionid 0x483fd50000
> 2016-09-13 05:09:28,694 [myid:] - INFO [main:LearnerZooKeeperServer@165] -
> Shutting down
> 2016-09-13 05:09:28,694 [myid:] - INFO [main:ZooKeeperServer@529] - shutting
> down
> 2016-09-13 05:09:28,694 [myid:] - INFO [main:FollowerRequestProcessor@138] -
> Shutting down
> 2016-09-13 05:09:28,695 [myid:127.0.0.1:13915] - INFO
> [main-SendThread(127.0.0.1:13915):ClientCnxn$SendThread@1231] - Unable to
> read additional data from server sessionid 0x483fd50000, likely server has
> closed socket, closing socket connection and attempting reconnect
> 2016-09-13 05:09:28,695 [myid:] - INFO [main:CommitProcessor@414] - Shutting
> down
> 2016-09-13 05:09:28,695 [myid:0] - INFO
> [FollowerRequestProcessor:0:FollowerRequestProcessor@109] -
> FollowerRequestProcessor exited loop!
> 2016-09-13 05:09:28,696 [myid:0] - INFO
> [CommitProcessor:0:CommitProcessor@299] - CommitProcessor exited loop!
> 2016-09-13 05:09:28,696 [myid:] - INFO [main:FinalRequestProcessor@479] -
> shutdown of request processor complete
> 2016-09-13 05:09:28,697 [myid:] - INFO [main:MBeanRegistry@128] - Unregister
> MBean
> [org.apache.ZooKeeperService:name0=ReplicatedServer_id0,name1=replica.0,name2=Follower,name3=InMemoryDataTree]
> 2016-09-13 05:09:28,697 [myid:] - INFO [main:SyncRequestProcessor@191] -
> Shutting down
> 2016-09-13 05:09:28,697 [myid:0] - INFO
> [SyncThread:0:SyncRequestProcessor@169] - SyncRequestProcessor exited!
> 2016-09-13 05:09:28,698 [myid:0] - INFO
> [ConnnectionExpirer:NIOServerCnxnFactory$ConnectionExpirerThread@583] -
> ConnnectionExpirerThread interrupted
> 2016-09-13 05:09:28,698 [myid:0] - INFO
> [NIOServerCxnFactory.AcceptThread:/127.0.0.1:13915:NIOServerCnxnFactory$AcceptThread@219]
> - accept thread exitted run method
> 2016-09-13 05:09:28,699 [myid:0] - INFO
> [NIOServerCxnFactory.SelectorThread-0:NIOServerCnxnFactory$SelectorThread@420]
> - selector thread exitted run method
> 2016-09-13 05:09:28,699 [myid:0] - INFO
> [/127.0.0.1:13917:QuorumCnxManager$Listener@661] - Leaving listener
> 2016-09-13 05:09:28,700 [myid:] - INFO [main:QuorumBase@398] - Shutting down
> leader election QuorumPeer[myid=0](plain=/127.0.0.1:13915)(secure=disabled)
> 2016-09-13 05:09:28,700 [myid:] - INFO [main:QuorumBase@403] - Waiting for
> QuorumPeer[myid=0](plain=/127.0.0.1:13915)(secure=disabled) to exit thread
> 2016-09-13 05:09:29,738 [myid:0] - INFO
> [WorkerReceiver[myid=0]:FastLeaderElection$Messenger$WorkerReceiver@440] -
> WorkerReceiver is down
> 2016-09-13 05:09:29,738 [myid:0] - INFO
> [WorkerSender[myid=0]:FastLeaderElection$Messenger$WorkerSender@470] -
> WorkerSender is down
> 2016-09-13 05:09:29,776 [myid:1] - INFO
> [WorkerReceiver[myid=1]:FastLeaderElection$Messenger$WorkerReceiver@440] -
> WorkerReceiver is down
> 2016-09-13 05:09:29,785 [myid:3] - INFO
> [WorkerSender[myid=3]:FastLeaderElection$Messenger$WorkerSender@470] -
> WorkerSender is down
> 2016-09-13 05:09:29,785 [myid:1] - INFO
> [WorkerSender[myid=1]:FastLeaderElection$Messenger$WorkerSender@470] -
> WorkerSender is down
> 2016-09-13 05:09:29,789 [myid:2] - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection$Messenger$WorkerReceiver@440] -
> WorkerReceiver is down
> 2016-09-13 05:09:29,790 [myid:2] - INFO
> [WorkerSender[myid=2]:FastLeaderElection$Messenger$WorkerSender@470] -
> WorkerSender is down
> 2016-09-13 05:09:29,792 [myid:3] - INFO
> [WorkerReceiver[myid=3]:FastLeaderElection$Messenger$WorkerReceiver@440] -
> WorkerReceiver is down
> 2016-09-13 05:09:29,922 [myid:0] - INFO
> [WorkerSender[myid=0]:FastLeaderElection$Messenger$WorkerSender@470] -
> WorkerSender is down
> 2016-09-13 05:09:29,923 [myid:0] - INFO
> [WorkerReceiver[myid=0]:FastLeaderElection$Messenger$WorkerReceiver@440] -
> WorkerReceiver is down
> 2016-09-13 05:09:30,255 [myid:0] - INFO
> [QuorumPeer[myid=0](plain=/127.0.0.1:13915)(secure=disabled):MBeanRegistry@128]
> - Unregister MBean
> [org.apache.ZooKeeperService:name0=ReplicatedServer_id0,name1=replica.0,name2=Follower]
> 2016-09-13 05:09:30,256 [myid:0] - INFO
> [QuorumPeer[myid=0](plain=/127.0.0.1:13915)(secure=disabled):Follower@198] -
> shutdown called
> java.lang.Exception: shutdown Follower
> at
> org.apache.zookeeper.server.quorum.Follower.shutdown(Follower.java:198)
> at
> org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:1115)
> 2016-09-13 05:09:30,256 [myid:0] - WARN
> [QuorumPeer[myid=0](plain=/127.0.0.1:13915)(secure=disabled):QuorumPeer@1158]
> - PeerState set to LOOKING
> 2016-09-13 05:09:30,256 [myid:0] - WARN
> [QuorumPeer[myid=0](plain=/127.0.0.1:13915)(secure=disabled):QuorumPeer@1140]
> - QuorumPeer main thread exited
> 2016-09-13 05:09:30,256 [myid:0] - INFO
> [QuorumPeer[myid=0](plain=/127.0.0.1:13915)(secure=disabled):MBeanRegistry@128]
> - Unregister MBean [org.apache.ZooKeeperService:name0=ReplicatedServer_id0]
> 2016-09-13 05:09:30,256 [myid:0] - INFO
> [QuorumPeer[myid=0](plain=/127.0.0.1:13915)(secure=disabled):MBeanRegistry@128]
> - Unregister MBean
> [org.apache.ZooKeeperService:name0=ReplicatedServer_id0,name1=replica.0]
> 2016-09-13 05:09:30,256 [myid:0] - INFO
> [QuorumPeer[myid=0](plain=/127.0.0.1:13915)(secure=disabled):MBeanRegistry@128]
> - Unregister MBean
> [org.apache.ZooKeeperService:name0=ReplicatedServer_id0,name1=replica.1]
> 2016-09-13 05:09:30,257 [myid:0] - INFO
> [QuorumPeer[myid=0](plain=/127.0.0.1:13915)(secure=disabled):MBeanRegistry@128]
> - Unregister MBean
> [org.apache.ZooKeeperService:name0=ReplicatedServer_id0,name1=replica.2]
> 2016-09-13 05:09:30,257 [myid:0] - INFO
> [QuorumPeer[myid=0](plain=/127.0.0.1:13915)(secure=disabled):MBeanRegistry@128]
> - Unregister MBean
> [org.apache.ZooKeeperService:name0=ReplicatedServer_id0,name1=replica.3]
> 2016-09-13 05:09:30,258 [myid:] - INFO [main:QuorumBase@394] - Shutting down
> quorum peer QuorumPeer[myid=1](plain=/127.0.0.1:13918)(secure=disabled)
> 2016-09-13 05:09:30,258 [myid:] - INFO [main:Follower@198] - shutdown called
> java.lang.Exception: shutdown Follower
> at
> org.apache.zookeeper.server.quorum.Follower.shutdown(Follower.java:198)
> at
> org.apache.zookeeper.server.quorum.QuorumPeer.shutdown(QuorumPeer.java:1184)
> at org.apache.zookeeper.test.QuorumBase.shutdown(QuorumBase.java:395)
> at
> org.apache.zookeeper.server.quorum.QuorumPeerTestBase$TestQPMain.shutdown(QuorumPeerTestBase.java:60)
> at
> org.apache.zookeeper.server.quorum.QuorumPeerTestBase$MainThread.shutdown(QuorumPeerTestBase.java:257)
> at
> org.apache.zookeeper.server.quorum.ReconfigDuringLeaderSyncTest.tearDown(ReconfigDuringLeaderSyncTest.java:189)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:606)
> at
> org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
> at
> org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
> at
> org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
> at
> org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:33)
> at org.junit.rules.TestWatchman$1.evaluate(TestWatchman.java:53)
> at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
> at
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
> at
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
> at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
> at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
> at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
> at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
> at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
> at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
> at junit.framework.JUnit4TestAdapter.run(JUnit4TestAdapter.java:38)
> at
> org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.run(JUnitTestRunner.java:535)
> at
> org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.launch(JUnitTestRunner.java:1182)
> at
> org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.main(JUnitTestRunner.java:1033)
> 2016-09-13 05:09:30,259 [myid:] - INFO [main:LearnerZooKeeperServer@165] -
> Shutting down
> 2016-09-13 05:09:30,259 [myid:] - INFO [main:ZooKeeperServer@529] - shutting
> down
> 2016-09-13 05:09:30,259 [myid:] - INFO [main:FollowerRequestProcessor@138] -
> Shutting down
> 2016-09-13 05:09:30,259 [myid:] - INFO [main:CommitProcessor@414] - Shutting
> down
> 2016-09-13 05:09:30,259 [myid:1] - INFO
> [FollowerRequestProcessor:1:FollowerRequestProcessor@109] -
> FollowerRequestProcessor exited loop!
> 2016-09-13 05:09:30,259 [myid:] - INFO [main:FinalRequestProcessor@479] -
> shutdown of request processor complete
> 2016-09-13 05:09:30,259 [myid:1] - INFO
> [CommitProcessor:1:CommitProcessor@299] - CommitProcessor exited loop!
> 2016-09-13 05:09:30,260 [myid:] - INFO [main:MBeanRegistry@128] - Unregister
> MBean
> [org.apache.ZooKeeperService:name0=ReplicatedServer_id1,name1=replica.1,name2=Follower,name3=InMemoryDataTree]
> 2016-09-13 05:09:30,260 [myid:] - INFO [main:SyncRequestProcessor@191] -
> Shutting down
> 2016-09-13 05:09:30,260 [myid:1] - INFO
> [SyncThread:1:SyncRequestProcessor@169] - SyncRequestProcessor exited!
> 2016-09-13 05:09:30,261 [myid:1] - INFO
> [ConnnectionExpirer:NIOServerCnxnFactory$ConnectionExpirerThread@583] -
> ConnnectionExpirerThread interrupted
> 2016-09-13 05:09:30,261 [myid:1] - INFO
> [NIOServerCxnFactory.AcceptThread:/127.0.0.1:13918:NIOServerCnxnFactory$AcceptThread@219]
> - accept thread exitted run method
> 2016-09-13 05:09:30,261 [myid:1] - INFO
> [NIOServerCxnFactory.SelectorThread-0:NIOServerCnxnFactory$SelectorThread@420]
> - selector thread exitted run method
> 2016-09-13 05:09:30,261 [myid:1] - INFO
> [/127.0.0.1:13920:QuorumCnxManager$Listener@661] - Leaving listener
> 2016-09-13 05:09:30,261 [myid:] - INFO [main:QuorumBase@398] - Shutting down
> leader election QuorumPeer[myid=1](plain=/127.0.0.1:13918)(secure=disabled)
> 2016-09-13 05:09:30,262 [myid:] - INFO [main:QuorumBase@403] - Waiting for
> QuorumPeer[myid=1](plain=/127.0.0.1:13918)(secure=disabled) to exit thread
> 2016-09-13 05:09:30,624 [myid:127.0.0.1:13915] - INFO
> [main-SendThread(127.0.0.1:13915):ClientCnxn$SendThread@1113] - Opening
> socket connection to server 127.0.0.1/127.0.0.1:13915. Will not attempt to
> authenticate using SASL (unknown error)
> 2016-09-13 05:09:30,624 [myid:127.0.0.1:13915] - WARN
> [main-SendThread(127.0.0.1:13915):ClientCnxn$SendThread@1235] - Session
> 0x483fd50000 for server 127.0.0.1/127.0.0.1:13915, unexpected error, closing
> socket connection and attempting reconnect
> java.net.ConnectException: Connection refused
> at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
> at
> sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:744)
> at
> org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:357)
> at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1214)
> 2016-09-13 05:09:31,733 [myid:127.0.0.1:13915] - INFO
> [main-SendThread(127.0.0.1:13915):ClientCnxn$SendThread@1113] - Opening
> socket connection to server 127.0.0.1/127.0.0.1:13915. Will not attempt to
> authenticate using SASL (unknown error)
> 2016-09-13 05:09:31,734 [myid:127.0.0.1:13915] - WARN
> [main-SendThread(127.0.0.1:13915):ClientCnxn$SendThread@1235] - Session
> 0x483fd50000 for server 127.0.0.1/127.0.0.1:13915, unexpected error, closing
> socket connection and attempting reconnect
> java.net.ConnectException: Connection refused
> at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
> at
> sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:744)
> at
> org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:357)
> at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1214)
> 2016-09-13 05:09:32,255 [myid:1] - INFO
> [QuorumPeer[myid=1](plain=/127.0.0.1:13918)(secure=disabled):MBeanRegistry@128]
> - Unregister MBean
> [org.apache.ZooKeeperService:name0=ReplicatedServer_id1,name1=replica.1,name2=Follower]
> 2016-09-13 05:09:32,256 [myid:1] - INFO
> [QuorumPeer[myid=1](plain=/127.0.0.1:13918)(secure=disabled):Follower@198] -
> shutdown called
> java.lang.Exception: shutdown Follower
> at
> org.apache.zookeeper.server.quorum.Follower.shutdown(Follower.java:198)
> at
> org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:1115)
> 2016-09-13 05:09:32,256 [myid:1] - WARN
> [QuorumPeer[myid=1](plain=/127.0.0.1:13918)(secure=disabled):QuorumPeer@1158]
> - PeerState set to LOOKING
> 2016-09-13 05:09:32,256 [myid:1] - WARN
> [QuorumPeer[myid=1](plain=/127.0.0.1:13918)(secure=disabled):QuorumPeer@1140]
> - QuorumPeer main thread exited
> 2016-09-13 05:09:32,256 [myid:1] - INFO
> [QuorumPeer[myid=1](plain=/127.0.0.1:13918)(secure=disabled):MBeanRegistry@128]
> - Unregister MBean [org.apache.ZooKeeperService:name0=ReplicatedServer_id1]
> 2016-09-13 05:09:32,257 [myid:1] - INFO
> [QuorumPeer[myid=1](plain=/127.0.0.1:13918)(secure=disabled):MBeanRegistry@128]
> - Unregister MBean
> [org.apache.ZooKeeperService:name0=ReplicatedServer_id1,name1=replica.1]
> 2016-09-13 05:09:32,257 [myid:1] - INFO
> [QuorumPeer[myid=1](plain=/127.0.0.1:13918)(secure=disabled):MBeanRegistry@128]
> - Unregister MBean
> [org.apache.ZooKeeperService:name0=ReplicatedServer_id1,name1=replica.0]
> 2016-09-13 05:09:32,257 [myid:1] - INFO
> [QuorumPeer[myid=1](plain=/127.0.0.1:13918)(secure=disabled):MBeanRegistry@128]
> - Unregister MBean
> [org.apache.ZooKeeperService:name0=ReplicatedServer_id1,name1=replica.2]
> 2016-09-13 05:09:32,257 [myid:1] - INFO
> [QuorumPeer[myid=1](plain=/127.0.0.1:13918)(secure=disabled):MBeanRegistry@128]
> - Unregister MBean
> [org.apache.ZooKeeperService:name0=ReplicatedServer_id1,name1=replica.3]
> 2016-09-13 05:09:32,257 [myid:] - INFO [main:QuorumBase@394] - Shutting down
> quorum peer QuorumPeer[myid=2](plain=/127.0.0.1:13921)(secure=disabled)
> 2016-09-13 05:09:32,258 [myid:] - INFO [main:Leader@623] - Shutting down
> 2016-09-13 05:09:32,258 [myid:] - INFO [main:Leader@629] - Shutdown called
> java.lang.Exception: shutdown Leader! reason: quorum Peer shutdown
> at org.apache.zookeeper.server.quorum.Leader.shutdown(Leader.java:629)
> at
> org.apache.zookeeper.server.quorum.QuorumPeer.shutdown(QuorumPeer.java:1181)
> at org.apache.zookeeper.test.QuorumBase.shutdown(QuorumBase.java:395)
> at
> org.apache.zookeeper.server.quorum.QuorumPeerTestBase$TestQPMain.shutdown(QuorumPeerTestBase.java:60)
> at
> org.apache.zookeeper.server.quorum.QuorumPeerTestBase$MainThread.shutdown(QuorumPeerTestBase.java:257)
> at
> org.apache.zookeeper.server.quorum.ReconfigDuringLeaderSyncTest.tearDown(ReconfigDuringLeaderSyncTest.java:189)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:606)
> at
> org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
> at
> org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
> at
> org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
> at
> org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:33)
> at org.junit.rules.TestWatchman$1.evaluate(TestWatchman.java:53)
> at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
> at
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
> at
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
> at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
> at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
> at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
> at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
> at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
> at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
> at junit.framework.JUnit4TestAdapter.run(JUnit4TestAdapter.java:38)
> at
> org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.run(JUnitTestRunner.java:535)
> at
> org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.launch(JUnitTestRunner.java:1182)
> at
> org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.main(JUnitTestRunner.java:1033)
> 2016-09-13 05:09:32,259 [myid:] - INFO [main:ZooKeeperServer@529] - shutting
> down
> 2016-09-13 05:09:32,259 [myid:] - INFO [main:SessionTrackerImpl@232] -
> Shutting down
> 2016-09-13 05:09:32,259 [myid:] - INFO [main:LeaderRequestProcessor@77] -
> Shutting down
> 2016-09-13 05:09:32,259 [myid:] - INFO [main:PrepRequestProcessor@965] -
> Shutting down
> 2016-09-13 05:09:32,259 [myid:] - INFO [main:ProposalRequestProcessor@88] -
> Shutting down
> 2016-09-13 05:09:32,259 [myid:2] - INFO [ProcessThread(sid:2
> cport:-1)::PrepRequestProcessor@154] - PrepRequestProcessor exited loop!
> 2016-09-13 05:09:32,259 [myid:] - INFO [main:CommitProcessor@414] - Shutting
> down
> 2016-09-13 05:09:32,260 [myid:2] - INFO
> [CommitProcessor:2:CommitProcessor@299] - CommitProcessor exited loop!
> 2016-09-13 05:09:32,260 [myid:] - INFO
> [main:Leader$ToBeAppliedRequestProcessor@924] - Shutting down
> 2016-09-13 05:09:32,260 [myid:] - INFO [main:FinalRequestProcessor@479] -
> shutdown of request processor complete
> 2016-09-13 05:09:32,261 [myid:] - INFO [main:SyncRequestProcessor@191] -
> Shutting down
> 2016-09-13 05:09:32,262 [myid:2] - INFO
> [SyncThread:2:SyncRequestProcessor@169] - SyncRequestProcessor exited!
> 2016-09-13 05:09:32,262 [myid:2] - INFO
> [LearnerCnxAcceptor-/127.0.0.1:13922:Leader$LearnerCnxAcceptor@373] -
> exception while shutting down acceptor: java.net.SocketException: Socket
> closed
> 2016-09-13 05:09:32,263 [myid:] - INFO [main:MBeanRegistry@128] - Unregister
> MBean
> [org.apache.ZooKeeperService:name0=ReplicatedServer_id2,name1=replica.2,name2=Leader,name3=InMemoryDataTree]
> 2016-09-13 05:09:32,264 [myid:2] - WARN
> [LearnerHandler-/127.0.0.1:39078:LearnerHandler@619] - ******* GOODBYE
> /127.0.0.1:39078 ********
> 2016-09-13 05:09:32,265 [myid:3] - WARN
> [QuorumPeer[myid=3](plain=/0:0:0:0:0:0:0:0:13924)(secure=disabled):Follower@93]
> - Exception when following the leader
> java.io.EOFException
> at java.io.DataInputStream.readInt(DataInputStream.java:392)
> at
> org.apache.jute.BinaryInputArchive.readInt(BinaryInputArchive.java:63)
> at
> org.apache.zookeeper.server.quorum.QuorumPacket.deserialize(QuorumPacket.java:83)
> at
> org.apache.jute.BinaryInputArchive.readRecord(BinaryInputArchive.java:99)
> at
> org.apache.zookeeper.server.quorum.Learner.readPacket(Learner.java:155)
> at
> org.apache.zookeeper.server.quorum.Follower.followLeader(Follower.java:89)
> at
> org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:1111)
> 2016-09-13 05:09:32,265 [myid:2] - WARN
> [LearnerHandler-/127.0.0.1:39079:LearnerHandler@619] - ******* GOODBYE
> /127.0.0.1:39079 ********
> 2016-09-13 05:09:32,265 [myid:2] - WARN
> [LearnerHandler-/127.0.0.1:39104:LearnerHandler@619] - ******* GOODBYE
> /127.0.0.1:39104 ********
> 2016-09-13 05:09:32,265 [myid:3] - INFO
> [QuorumPeer[myid=3](plain=/0:0:0:0:0:0:0:0:13924)(secure=disabled):MBeanRegistry@128]
> - Unregister MBean
> [org.apache.ZooKeeperService:name0=ReplicatedServer_id3,name1=replica.3,name2=Follower]
> 2016-09-13 05:09:32,265 [myid:2] - WARN
> [LearnerHandler-/127.0.0.1:39104:LearnerHandler@903] - Ignoring unexpected
> exception
> java.lang.InterruptedException
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireInterruptibly(AbstractQueuedSynchronizer.java:1219)
> at
> java.util.concurrent.locks.ReentrantLock.lockInterruptibly(ReentrantLock.java:340)
> at
> java.util.concurrent.LinkedBlockingQueue.put(LinkedBlockingQueue.java:338)
> at
> org.apache.zookeeper.server.quorum.LearnerHandler.shutdown(LearnerHandler.java:901)
> at
> org.apache.zookeeper.server.quorum.LearnerHandler.run(LearnerHandler.java:622)
> 2016-09-13 05:09:32,265 [myid:3] - INFO
> [QuorumPeer[myid=3](plain=/0:0:0:0:0:0:0:0:13924)(secure=disabled):Follower@198]
> - shutdown called
> java.lang.Exception: shutdown Follower
> at
> org.apache.zookeeper.server.quorum.Follower.shutdown(Follower.java:198)
> at
> org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:1115)
> 2016-09-13 05:09:32,266 [myid:2] - INFO
> [NIOServerCxnFactory.AcceptThread:/127.0.0.1:13921:NIOServerCnxnFactory$AcceptThread@219]
> - accept thread exitted run method
> 2016-09-13 05:09:32,266 [myid:3] - INFO
> [QuorumPeer[myid=3](plain=/0:0:0:0:0:0:0:0:13924)(secure=disabled):MBeanRegistry@128]
> - Unregister MBean
> [org.apache.ZooKeeperService:name0=ReplicatedServer_id3,name1=replica.3,name2=Follower,name3=Connections,name4=127.0.0.1,name5=0x3000048422c0000]
> 2016-09-13 05:09:32,266 [myid:2] - INFO
> [NIOServerCxnFactory.SelectorThread-0:NIOServerCnxnFactory$SelectorThread@420]
> - selector thread exitted run method
> 2016-09-13 05:09:32,266 [myid:2] - INFO
> [ConnnectionExpirer:NIOServerCnxnFactory$ConnectionExpirerThread@583] -
> ConnnectionExpirerThread interrupted
> 2016-09-13 05:09:32,266 [myid:3] - INFO
> [QuorumPeer[myid=3](plain=/0:0:0:0:0:0:0:0:13924)(secure=disabled):NIOServerCnxn@607]
> - Closed socket connection for client /127.0.0.1:50397 which had sessionid
> 0x3000048422c0000
> 2016-09-13 05:09:32,267 [myid:3] - INFO
> [QuorumPeer[myid=3](plain=/0:0:0:0:0:0:0:0:13924)(secure=disabled):LearnerZooKeeperServer@165]
> - Shutting down
> 2016-09-13 05:09:32,267 [myid:3] - INFO
> [QuorumPeer[myid=3](plain=/0:0:0:0:0:0:0:0:13924)(secure=disabled):ZooKeeperServer@529]
> - shutting down
> 2016-09-13 05:09:32,267 [myid:3] - INFO
> [QuorumPeer[myid=3](plain=/0:0:0:0:0:0:0:0:13924)(secure=disabled):FollowerRequestProcessor@138]
> - Shutting down
> 2016-09-13 05:09:32,267 [myid:3] - INFO
> [QuorumPeer[myid=3](plain=/0:0:0:0:0:0:0:0:13924)(secure=disabled):CommitProcessor@414]
> - Shutting down
> 2016-09-13 05:09:32,267 [myid:127.0.0.1:13924] - INFO
> [main-SendThread(127.0.0.1:13924):ClientCnxn$SendThread@1231] - Unable to
> read additional data from server sessionid 0x3000048422c0000, likely server
> has closed socket, closing socket connection and attempting reconnect
> 2016-09-13 05:09:32,268 [myid:3] - INFO
> [FollowerRequestProcessor:3:FollowerRequestProcessor@109] -
> FollowerRequestProcessor exited loop!
> 2016-09-13 05:09:32,268 [myid:3] - INFO
> [CommitProcessor:3:CommitProcessor@299] - CommitProcessor exited loop!
> 2016-09-13 05:09:32,268 [myid:3] - INFO
> [QuorumPeer[myid=3](plain=/0:0:0:0:0:0:0:0:13924)(secure=disabled):FinalRequestProcessor@479]
> - shutdown of request processor complete
> 2016-09-13 05:09:32,269 [myid:3] - INFO
> [QuorumPeer[myid=3](plain=/0:0:0:0:0:0:0:0:13924)(secure=disabled):MBeanRegistry@128]
> - Unregister MBean
> [org.apache.ZooKeeperService:name0=ReplicatedServer_id3,name1=replica.3,name2=Follower,name3=InMemoryDataTree]
> 2016-09-13 05:09:32,269 [myid:3] - INFO
> [QuorumPeer[myid=3](plain=/0:0:0:0:0:0:0:0:13924)(secure=disabled):SyncRequestProcessor@191]
> - Shutting down
> 2016-09-13 05:09:32,269 [myid:3] - INFO
> [SyncThread:3:SyncRequestProcessor@169] - SyncRequestProcessor exited!
> 2016-09-13 05:09:32,269 [myid:3] - WARN
> [QuorumPeer[myid=3](plain=/0:0:0:0:0:0:0:0:13924)(secure=disabled):QuorumPeer@1158]
> - PeerState set to LOOKING
> 2016-09-13 05:09:32,269 [myid:3] - INFO
> [QuorumPeer[myid=3](plain=/0:0:0:0:0:0:0:0:13924)(secure=disabled):QuorumPeer@1033]
> - LOOKING
> 2016-09-13 05:09:32,270 [myid:3] - INFO
> [QuorumPeer[myid=3](plain=/0:0:0:0:0:0:0:0:13924)(secure=disabled):FileSnap@83]
> - Reading snapshot
> /home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk-openjdk7/build/test/tmp/test1465497725988500626.junit.dir/data/version-2/snapshot.100000001
> 2016-09-13 05:09:32,271 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/127.0.0.1:13921)(secure=disabled):MBeanRegistry@128]
> - Unregister MBean
> [org.apache.ZooKeeperService:name0=ReplicatedServer_id2,name1=replica.2,name2=Leader]
> 2016-09-13 05:09:32,272 [myid:2] - WARN
> [QuorumPeer[myid=2](plain=/127.0.0.1:13921)(secure=disabled):QuorumPeer@1127]
> - Unexpected exception
> java.lang.InterruptedException
> at java.lang.Object.wait(Native Method)
> at org.apache.zookeeper.server.quorum.Leader.lead(Leader.java:561)
> at
> org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:1124)
> 2016-09-13 05:09:32,272 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/127.0.0.1:13921)(secure=disabled):Leader@623] -
> Shutting down
> 2016-09-13 05:09:32,272 [myid:2] - WARN
> [QuorumPeer[myid=2](plain=/127.0.0.1:13921)(secure=disabled):QuorumPeer@1158]
> - PeerState set to LOOKING
> 2016-09-13 05:09:32,272 [myid:2] - WARN
> [QuorumPeer[myid=2](plain=/127.0.0.1:13921)(secure=disabled):QuorumPeer@1140]
> - QuorumPeer main thread exited
> 2016-09-13 05:09:32,272 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/127.0.0.1:13921)(secure=disabled):MBeanRegistry@128]
> - Unregister MBean [org.apache.ZooKeeperService:name0=ReplicatedServer_id2]
> 2016-09-13 05:09:32,272 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/127.0.0.1:13921)(secure=disabled):MBeanRegistry@128]
> - Unregister MBean
> [org.apache.ZooKeeperService:name0=ReplicatedServer_id2,name1=replica.2]
> 2016-09-13 05:09:32,272 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/127.0.0.1:13921)(secure=disabled):MBeanRegistry@128]
> - Unregister MBean
> [org.apache.ZooKeeperService:name0=ReplicatedServer_id2,name1=replica.0]
> 2016-09-13 05:09:32,273 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/127.0.0.1:13921)(secure=disabled):MBeanRegistry@128]
> - Unregister MBean
> [org.apache.ZooKeeperService:name0=ReplicatedServer_id2,name1=replica.1]
> 2016-09-13 05:09:32,273 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/127.0.0.1:13921)(secure=disabled):MBeanRegistry@128]
> - Unregister MBean
> [org.apache.ZooKeeperService:name0=ReplicatedServer_id2,name1=replica.3]
> 2016-09-13 05:09:32,274 [myid:2] - INFO
> [/127.0.0.1:13923:QuorumCnxManager$Listener@661] - Leaving listener
> 2016-09-13 05:09:32,274 [myid:] - INFO [main:QuorumBase@398] - Shutting down
> leader election QuorumPeer[myid=2](plain=/127.0.0.1:13921)(secure=disabled)
> 2016-09-13 05:09:32,274 [myid:] - INFO [main:QuorumBase@403] - Waiting for
> QuorumPeer[myid=2](plain=/127.0.0.1:13921)(secure=disabled) to exit thread
> 2016-09-13 05:09:32,274 [myid:] - INFO [main:QuorumBase@394] - Shutting down
> quorum peer QuorumPeer[myid=3](plain=/0:0:0:0:0:0:0:0:13924)(secure=disabled)
> 2016-09-13 05:09:32,275 [myid:3] - INFO
> [ConnnectionExpirer:NIOServerCnxnFactory$ConnectionExpirerThread@583] -
> ConnnectionExpirerThread interrupted
> 2016-09-13 05:09:32,275 [myid:3] - INFO
> [NIOServerCxnFactory.AcceptThread:0.0.0.0/0.0.0.0:13924:NIOServerCnxnFactory$AcceptThread@219]
> - accept thread exitted run method
> 2016-09-13 05:09:32,276 [myid:3] - INFO
> [NIOServerCxnFactory.SelectorThread-0:NIOServerCnxnFactory$SelectorThread@420]
> - selector thread exitted run method
> 2016-09-13 05:09:32,276 [myid:3] - INFO
> [QuorumPeer[myid=3](plain=/0:0:0:0:0:0:0:0:13924)(secure=disabled):FastLeaderElection@894]
> - New election. My id = 3, proposed zxid=0x100000004
> 2016-09-13 05:09:32,277 [myid:3] - WARN
> [WorkerSender[myid=3]:QuorumCnxManager@455] - Cannot open channel to 0 at
> election address /127.0.0.1:13917
> java.net.ConnectException: Connection refused
> at java.net.PlainSocketImpl.socketConnect(Native Method)
> at
> java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:339)
> at
> java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:200)
> at
> java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:182)
> at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
> at java.net.Socket.connect(Socket.java:579)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.connectOne(QuorumCnxManager.java:441)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.connectOne(QuorumCnxManager.java:482)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.toSend(QuorumCnxManager.java:419)
> at
> org.apache.zookeeper.server.quorum.FastLeaderElection$Messenger$WorkerSender.process(FastLeaderElection.java:486)
> at
> org.apache.zookeeper.server.quorum.FastLeaderElection$Messenger$WorkerSender.run(FastLeaderElection.java:465)
> at java.lang.Thread.run(Thread.java:745)
> 2016-09-13 05:09:32,277 [myid:3] - INFO
> [/127.0.0.1:13926:QuorumCnxManager$Listener@661] - Leaving listener
> 2016-09-13 05:09:32,277 [myid:3] - WARN
> [WorkerSender[myid=3]:QuorumCnxManager@455] - Cannot open channel to 0 at
> election address /127.0.0.1:13917
> java.net.ConnectException: Connection refused
> at java.net.PlainSocketImpl.socketConnect(Native Method)
> at
> java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:339)
> at
> java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:200)
> at
> java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:182)
> at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
> at java.net.Socket.connect(Socket.java:579)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.connectOne(QuorumCnxManager.java:441)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.connectOne(QuorumCnxManager.java:489)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.toSend(QuorumCnxManager.java:419)
> at
> org.apache.zookeeper.server.quorum.FastLeaderElection$Messenger$WorkerSender.process(FastLeaderElection.java:486)
> at
> org.apache.zookeeper.server.quorum.FastLeaderElection$Messenger$WorkerSender.run(FastLeaderElection.java:465)
> at java.lang.Thread.run(Thread.java:745)
> 2016-09-13 05:09:32,278 [myid:3] - WARN
> [WorkerSender[myid=3]:QuorumCnxManager@455] - Cannot open channel to 1 at
> election address /127.0.0.1:13920
> java.net.ConnectException: Connection refused
> at java.net.PlainSocketImpl.socketConnect(Native Method)
> at
> java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:339)
> at
> java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:200)
> at
> java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:182)
> at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
> at java.net.Socket.connect(Socket.java:579)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.connectOne(QuorumCnxManager.java:441)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.connectOne(QuorumCnxManager.java:482)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.toSend(QuorumCnxManager.java:419)
> at
> org.apache.zookeeper.server.quorum.FastLeaderElection$Messenger$WorkerSender.process(FastLeaderElection.java:486)
> at
> org.apache.zookeeper.server.quorum.FastLeaderElection$Messenger$WorkerSender.run(FastLeaderElection.java:465)
> at java.lang.Thread.run(Thread.java:745)
> 2016-09-13 05:09:32,278 [myid:] - INFO [main:QuorumBase@398] - Shutting down
> leader election
> QuorumPeer[myid=3](plain=/0:0:0:0:0:0:0:0:13924)(secure=disabled)
> 2016-09-13 05:09:32,279 [myid:] - INFO [main:QuorumBase@403] - Waiting for
> QuorumPeer[myid=3](plain=/0:0:0:0:0:0:0:0:13924)(secure=disabled) to exit
> thread
> 2016-09-13 05:09:32,279 [myid:3] - WARN
> [WorkerSender[myid=3]:QuorumCnxManager@455] - Cannot open channel to 1 at
> election address /127.0.0.1:13920
> java.net.ConnectException: Connection refused
> at java.net.PlainSocketImpl.socketConnect(Native Method)
> at
> java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:339)
> at
> java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:200)
> at
> java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:182)
> at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
> at java.net.Socket.connect(Socket.java:579)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.connectOne(QuorumCnxManager.java:441)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.connectOne(QuorumCnxManager.java:489)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.toSend(QuorumCnxManager.java:419)
> at
> org.apache.zookeeper.server.quorum.FastLeaderElection$Messenger$WorkerSender.process(FastLeaderElection.java:486)
> at
> org.apache.zookeeper.server.quorum.FastLeaderElection$Messenger$WorkerSender.run(FastLeaderElection.java:465)
> at java.lang.Thread.run(Thread.java:745)
> 2016-09-13 05:09:32,280 [myid:3] - INFO
> [WorkerSender[myid=3]:FastLeaderElection$Messenger$WorkerSender@470] -
> WorkerSender is down
> 2016-09-13 05:09:32,280 [myid:3] - INFO
> [QuorumPeer[myid=3](plain=/0:0:0:0:0:0:0:0:13924)(secure=disabled):MBeanRegistry@128]
> - Unregister MBean
> [org.apache.ZooKeeperService:name0=ReplicatedServer_id3,name1=replica.3,name2=LeaderElection]
> 2016-09-13 05:09:32,280 [myid:3] - WARN
> [QuorumPeer[myid=3](plain=/0:0:0:0:0:0:0:0:13924)(secure=disabled):QuorumPeer@1140]
> - QuorumPeer main thread exited
> 2016-09-13 05:09:32,280 [myid:3] - INFO
> [QuorumPeer[myid=3](plain=/0:0:0:0:0:0:0:0:13924)(secure=disabled):MBeanRegistry@128]
> - Unregister MBean [org.apache.ZooKeeperService:name0=ReplicatedServer_id3]
> 2016-09-13 05:09:32,280 [myid:3] - INFO
> [QuorumPeer[myid=3](plain=/0:0:0:0:0:0:0:0:13924)(secure=disabled):MBeanRegistry@128]
> - Unregister MBean
> [org.apache.ZooKeeperService:name0=ReplicatedServer_id3,name1=replica.3]
> 2016-09-13 05:09:32,281 [myid:3] - INFO
> [QuorumPeer[myid=3](plain=/0:0:0:0:0:0:0:0:13924)(secure=disabled):MBeanRegistry@128]
> - Unregister MBean
> [org.apache.ZooKeeperService:name0=ReplicatedServer_id3,name1=replica.0]
> 2016-09-13 05:09:32,281 [myid:3] - INFO
> [QuorumPeer[myid=3](plain=/0:0:0:0:0:0:0:0:13924)(secure=disabled):MBeanRegistry@128]
> - Unregister MBean
> [org.apache.ZooKeeperService:name0=ReplicatedServer_id3,name1=replica.1]
> 2016-09-13 05:09:32,281 [myid:3] - INFO
> [QuorumPeer[myid=3](plain=/0:0:0:0:0:0:0:0:13924)(secure=disabled):MBeanRegistry@128]
> - Unregister MBean
> [org.apache.ZooKeeperService:name0=ReplicatedServer_id3,name1=replica.2]
> 2016-09-13 05:09:32,283 [myid:] - INFO [main:ZKTestCase$1@70] - FAILED
> testDuringLeaderSync
> java.lang.AssertionError: zoo.cfg.dynamic.next is not deleted.
> at org.junit.Assert.fail(Assert.java:88)
> at org.junit.Assert.assertTrue(Assert.java:41)
> at org.junit.Assert.assertFalse(Assert.java:64)
> at
> org.apache.zookeeper.server.quorum.ReconfigDuringLeaderSyncTest.testDuringLeaderSync(ReconfigDuringLeaderSyncTest.java:155)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:606)
> at
> org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
> at
> org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
> at
> org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
> at
> org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
> at
> org.apache.zookeeper.JUnit4ZKTestRunner$LoggedInvokeMethod.evaluate(JUnit4ZKTestRunner.java:79)
> at
> org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
> at org.junit.rules.TestWatchman$1.evaluate(TestWatchman.java:53)
> at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
> at
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
> at
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
> at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
> at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
> at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
> at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
> at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
> at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
> at junit.framework.JUnit4TestAdapter.run(JUnit4TestAdapter.java:38)
> at
> org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.run(JUnitTestRunner.java:535)
> at
> org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.launch(JUnitTestRunner.java:1182)
> at
> org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.main(JUnitTestRunner.java:1033)
> 2016-09-13 05:09:32,284 [myid:] - INFO [main:ZKTestCase$1@60] - FINISHED
> testDuringLeaderSync
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.4.14#64029)
