[ZOOKEEPER-2529] Flaky Test: org.apache.zookeeper.test.NonRecoverableErrorTest.testZooKeeperServiceAvailableOnLeader - ASF JIRA

XML

Word

Printable

JSON

Details

Type: Sub-task
Status: Resolved
Priority: Major
Resolution: Cannot Reproduce
Affects Version/s: 3.4.9, 3.5.3
Fix Version/s: None
Component/s: None
Labels:
- flaky
- flaky-test

Description

This flaky is introduced by ~~ZOOKEEPER-2247~~ recently.

Error Message

IOException is expected due to error injected to transaction log commit
Stacktrace

junit.framework.AssertionFailedError: IOException is expected due to error injected to transaction log commit
	at org.apache.zookeeper.test.NonRecoverableErrorTest.testZooKeeperServiceAvailableOnLeader(NonRecoverableErrorTest.java:115)
	at org.apache.zookeeper.JUnit4ZKTestRunner$LoggedInvokeMethod.evaluate(JUnit4ZKTestRunner.java:79)
	at java.util.concurrent.FutureTask.run(FutureTask.java:262)
	at java.lang.Thread.run(Thread.java:745)
Standard Output

2016-08-24 19:20:17,000 [myid:] - INFO  [main:JUnit4ZKTestRunner@47] - No test.method specified. using default methods.
2016-08-24 19:20:17,142 [myid:] - INFO  [main:JUnit4ZKTestRunner@47] - No test.method specified. using default methods.
2016-08-24 19:20:17,215 [myid:] - INFO  [main:ZKTestCase$1@55] - STARTING testZooKeeperServiceAvailableOnLeader
2016-08-24 19:20:17,222 [myid:] - INFO  [Time-limited test:JUnit4ZKTestRunner$LoggedInvokeMethod@77] - RUNNING TEST METHOD testZooKeeperServiceAvailableOnLeader
2016-08-24 19:20:17,228 [myid:] - INFO  [Time-limited test:PortAssignment@151] - Test process 1/8 using ports from 11221 - 13913.
2016-08-24 19:20:17,230 [myid:] - INFO  [Time-limited test:PortAssignment@85] - Assigned port 11222 from range 11221 - 13913.
2016-08-24 19:20:17,231 [myid:] - INFO  [Time-limited test:PortAssignment@85] - Assigned port 11223 from range 11221 - 13913.
2016-08-24 19:20:17,231 [myid:] - INFO  [Time-limited test:PortAssignment@85] - Assigned port 11224 from range 11221 - 13913.
2016-08-24 19:20:17,232 [myid:] - INFO  [Time-limited test:PortAssignment@85] - Assigned port 11225 from range 11221 - 13913.
2016-08-24 19:20:17,232 [myid:] - INFO  [Time-limited test:PortAssignment@85] - Assigned port 11226 from range 11221 - 13913.
2016-08-24 19:20:17,232 [myid:] - INFO  [Time-limited test:PortAssignment@85] - Assigned port 11227 from range 11221 - 13913.
2016-08-24 19:20:17,233 [myid:] - INFO  [Time-limited test:PortAssignment@85] - Assigned port 11228 from range 11221 - 13913.
2016-08-24 19:20:17,233 [myid:] - INFO  [Time-limited test:PortAssignment@85] - Assigned port 11229 from range 11221 - 13913.
2016-08-24 19:20:17,234 [myid:] - INFO  [Time-limited test:PortAssignment@85] - Assigned port 11230 from range 11221 - 13913.
2016-08-24 19:20:17,256 [myid:] - INFO  [Time-limited test:QuorumPeerTestBase$MainThread@131] - id = 0 tmpDir = /home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/test/tmp/test7330020881446886387.junit.dir clientPort = 11222 adminServerPort = 8080
2016-08-24 19:20:17,262 [myid:] - INFO  [Time-limited test:QuorumPeerTestBase$MainThread@131] - id = 1 tmpDir = /home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/test/tmp/test7260737707555606353.junit.dir clientPort = 11225 adminServerPort = 8080
2016-08-24 19:20:17,267 [myid:] - INFO  [Time-limited test:QuorumPeerTestBase$MainThread@131] - id = 2 tmpDir = /home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/test/tmp/test1038022970424066351.junit.dir clientPort = 11228 adminServerPort = 8080
2016-08-24 19:20:17,268 [myid:] - INFO  [Thread-1:QuorumPeerConfig@116] - Reading configuration from: /home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/test/tmp/test7260737707555606353.junit.dir/zoo.cfg
2016-08-24 19:20:17,268 [myid:] - INFO  [Thread-0:QuorumPeerConfig@116] - Reading configuration from: /home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/test/tmp/test7330020881446886387.junit.dir/zoo.cfg
2016-08-24 19:20:17,269 [myid:] - INFO  [Thread-2:QuorumPeerConfig@116] - Reading configuration from: /home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/test/tmp/test1038022970424066351.junit.dir/zoo.cfg
2016-08-24 19:20:17,270 [myid:] - INFO  [Thread-1:QuorumPeerConfig@318] - clientPortAddress is 0.0.0.0/0.0.0.0:11225
2016-08-24 19:20:17,270 [myid:] - INFO  [Thread-0:QuorumPeerConfig@318] - clientPortAddress is 0.0.0.0/0.0.0.0:11222
2016-08-24 19:20:17,271 [myid:] - INFO  [Thread-0:QuorumPeerConfig@322] - secureClientPort is not set
2016-08-24 19:20:17,270 [myid:] - INFO  [Thread-1:QuorumPeerConfig@322] - secureClientPort is not set
2016-08-24 19:20:17,270 [myid:] - INFO  [Thread-2:QuorumPeerConfig@318] - clientPortAddress is 0.0.0.0/0.0.0.0:11228
2016-08-24 19:20:17,271 [myid:] - INFO  [Thread-2:QuorumPeerConfig@322] - secureClientPort is not set
2016-08-24 19:20:17,276 [myid:] - INFO  [Time-limited test:FourLetterWordMain@85] - connecting to 127.0.0.1 11222
2016-08-24 19:20:17,280 [myid:] - INFO  [Time-limited test:ClientBase@248] - server 127.0.0.1:11222 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.test.NonRecoverableErrorTest.testZooKeeperServiceAvailableOnLeader(NonRecoverableErrorTest.java:77)
	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.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:298)
	at org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:292)
	at java.util.concurrent.FutureTask.run(FutureTask.java:262)
	at java.lang.Thread.run(Thread.java:745)
2016-08-24 19:20:17,295 [myid:1] - INFO  [Thread-1:DatadirCleanupManager@78] - autopurge.snapRetainCount set to 3
2016-08-24 19:20:17,295 [myid:2] - INFO  [Thread-2:DatadirCleanupManager@78] - autopurge.snapRetainCount set to 3
2016-08-24 19:20:17,295 [myid:2] - INFO  [Thread-2:DatadirCleanupManager@79] - autopurge.purgeInterval set to 0
2016-08-24 19:20:17,295 [myid:2] - INFO  [Thread-2:DatadirCleanupManager@101] - Purge task is not scheduled.
2016-08-24 19:20:17,295 [myid:1] - INFO  [Thread-1:DatadirCleanupManager@79] - autopurge.purgeInterval set to 0
2016-08-24 19:20:17,296 [myid:1] - INFO  [Thread-1:DatadirCleanupManager@101] - Purge task is not scheduled.
2016-08-24 19:20:17,297 [myid:2] - INFO  [Thread-2:ManagedUtil@46] - Log4j found with jmx enabled.
2016-08-24 19:20:17,298 [myid:1] - INFO  [Thread-1:ManagedUtil@46] - Log4j found with jmx enabled.
2016-08-24 19:20:17,300 [myid:0] - INFO  [Thread-0:DatadirCleanupManager@78] - autopurge.snapRetainCount set to 3
2016-08-24 19:20:17,300 [myid:0] - INFO  [Thread-0:DatadirCleanupManager@79] - autopurge.purgeInterval set to 0
2016-08-24 19:20:17,300 [myid:0] - INFO  [Thread-0:DatadirCleanupManager@101] - Purge task is not scheduled.
2016-08-24 19:20:17,300 [myid:0] - INFO  [Thread-0:ManagedUtil@46] - Log4j found with jmx enabled.
2016-08-24 19:20:17,417 [myid:2] - ERROR [Thread-2: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-08-24 19:20:17,418 [myid:2] - WARN  [Thread-2: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-08-24 19:20:17,425 [myid:2] - INFO  [Thread-2:QuorumPeerMain@136] - Starting quorum peer
2016-08-24 19:20:17,443 [myid:2] - INFO  [Thread-2:NIOServerCnxnFactory@673] - Configuring NIO connection handler with 10s sessionless connection timeout, 2 selector thread(s), 32 worker threads, and 64 kB direct buffers.
2016-08-24 19:20:17,444 [myid:0] - ERROR [Thread-0: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-08-24 19:20:17,445 [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-08-24 19:20:17,446 [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-08-24 19:20:17,447 [myid:0] - INFO  [Thread-0:QuorumPeerMain@136] - Starting quorum peer
2016-08-24 19:20:17,447 [myid:0] - INFO  [Thread-0:NIOServerCnxnFactory@673] - Configuring NIO connection handler with 10s sessionless connection timeout, 2 selector thread(s), 32 worker threads, and 64 kB direct buffers.
2016-08-24 19:20:17,454 [myid:0] - INFO  [Thread-0:NIOServerCnxnFactory@686] - binding to port /127.0.0.1:11222
2016-08-24 19:20:17,454 [myid:2] - INFO  [Thread-2:NIOServerCnxnFactory@686] - binding to port /127.0.0.1:11228
2016-08-24 19:20:17,473 [myid:1] - INFO  [Thread-1:QuorumPeerMain@136] - Starting quorum peer
2016-08-24 19:20:17,473 [myid:1] - INFO  [Thread-1:NIOServerCnxnFactory@673] - Configuring NIO connection handler with 10s sessionless connection timeout, 2 selector thread(s), 32 worker threads, and 64 kB direct buffers.
2016-08-24 19:20:17,474 [myid:1] - INFO  [Thread-1:NIOServerCnxnFactory@686] - binding to port /127.0.0.1:11225
2016-08-24 19:20:17,488 [myid:0] - INFO  [Thread-0:QuorumPeer@1327] - Local sessions disabled
2016-08-24 19:20:17,488 [myid:2] - INFO  [Thread-2:QuorumPeer@1327] - Local sessions disabled
2016-08-24 19:20:17,488 [myid:1] - INFO  [Thread-1:QuorumPeer@1327] - Local sessions disabled
2016-08-24 19:20:17,488 [myid:2] - INFO  [Thread-2:QuorumPeer@1338] - Local session upgrading disabled
2016-08-24 19:20:17,488 [myid:0] - INFO  [Thread-0:QuorumPeer@1338] - Local session upgrading disabled
2016-08-24 19:20:17,488 [myid:0] - INFO  [Thread-0:QuorumPeer@1305] - tickTime set to 4000
2016-08-24 19:20:17,488 [myid:2] - INFO  [Thread-2:QuorumPeer@1305] - tickTime set to 4000
2016-08-24 19:20:17,489 [myid:2] - INFO  [Thread-2:QuorumPeer@1349] - minSessionTimeout set to 8000
2016-08-24 19:20:17,489 [myid:2] - INFO  [Thread-2:QuorumPeer@1360] - maxSessionTimeout set to 80000
2016-08-24 19:20:17,489 [myid:2] - INFO  [Thread-2:QuorumPeer@1375] - initLimit set to 10
2016-08-24 19:20:17,488 [myid:1] - INFO  [Thread-1:QuorumPeer@1338] - Local session upgrading disabled
2016-08-24 19:20:17,490 [myid:1] - INFO  [Thread-1:QuorumPeer@1305] - tickTime set to 4000
2016-08-24 19:20:17,490 [myid:1] - INFO  [Thread-1:QuorumPeer@1349] - minSessionTimeout set to 8000
2016-08-24 19:20:17,490 [myid:1] - INFO  [Thread-1:QuorumPeer@1360] - maxSessionTimeout set to 80000
2016-08-24 19:20:17,490 [myid:1] - INFO  [Thread-1:QuorumPeer@1375] - initLimit set to 10
2016-08-24 19:20:17,488 [myid:0] - INFO  [Thread-0:QuorumPeer@1349] - minSessionTimeout set to 8000
2016-08-24 19:20:17,491 [myid:0] - INFO  [Thread-0:QuorumPeer@1360] - maxSessionTimeout set to 80000
2016-08-24 19:20:17,491 [myid:0] - INFO  [Thread-0:QuorumPeer@1375] - initLimit set to 10
2016-08-24 19:20:17,514 [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-08-24 19:20:17,514 [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-08-24 19:20:17,515 [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-08-24 19:20:17,516 [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-08-24 19:20:17,516 [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-08-24 19:20:17,521 [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-08-24 19:20:17,535 [myid:] - INFO  [Time-limited test:FourLetterWordMain@85] - connecting to 127.0.0.1 11222
2016-08-24 19:20:17,539 [myid:0] - INFO  [NIOServerCxnFactory.AcceptThread:/127.0.0.1:11222:NIOServerCnxnFactory$AcceptThread@296] - Accepted socket connection from /127.0.0.1:41083
2016-08-24 19:20:17,554 [myid:0] - INFO  [NIOWorkerThread-1:NIOServerCnxn@485] - Processing stat command from /127.0.0.1:41083
2016-08-24 19:20:17,568 [myid:0] - INFO  [NIOWorkerThread-1:NIOServerCnxn@607] - Closed socket connection for client /127.0.0.1:41083 (no session established for client)
2016-08-24 19:20:17,595 [myid:0] - INFO  [QuorumPeerListener:QuorumCnxManager$Listener@632] - My election bind port: /127.0.0.1:11224
2016-08-24 19:20:17,606 [myid:1] - INFO  [QuorumPeerListener:QuorumCnxManager$Listener@632] - My election bind port: /127.0.0.1:11227
2016-08-24 19:20:17,607 [myid:0] - INFO  [QuorumPeer[myid=0](plain=/127.0.0.1:11222)(secure=disabled):QuorumPeer@1033] - LOOKING
2016-08-24 19:20:17,611 [myid:1] - INFO  [QuorumPeer[myid=1](plain=/127.0.0.1:11225)(secure=disabled):QuorumPeer@1033] - LOOKING
2016-08-24 19:20:17,624 [myid:0] - INFO  [QuorumPeer[myid=0](plain=/127.0.0.1:11222)(secure=disabled):FastLeaderElection@894] - New election. My id =  0, proposed zxid=0x0
2016-08-24 19:20:17,626 [myid:1] - INFO  [QuorumPeer[myid=1](plain=/127.0.0.1:11225)(secure=disabled):FastLeaderElection@894] - New election. My id =  1, proposed zxid=0x0
2016-08-24 19:20:17,634 [myid:2] - INFO  [QuorumPeerListener:QuorumCnxManager$Listener@632] - My election bind port: /127.0.0.1:11230
2016-08-24 19:20:17,640 [myid:2] - INFO  [QuorumPeer[myid=2](plain=/127.0.0.1:11228)(secure=disabled):QuorumPeer@1033] - LOOKING
2016-08-24 19:20:17,640 [myid:2] - INFO  [QuorumPeer[myid=2](plain=/127.0.0.1:11228)(secure=disabled):FastLeaderElection@894] - New election. My id =  2, proposed zxid=0x0
2016-08-24 19:20:17,642 [myid:0] - INFO  [/127.0.0.1:11224:QuorumCnxManager$Listener@638] - Received connection request /127.0.0.1:45368
2016-08-24 19:20:17,645 [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-08-24 19:20:17,649 [myid:0] - INFO  [/127.0.0.1:11224:QuorumCnxManager$Listener@638] - Received connection request /127.0.0.1:45369
2016-08-24 19:20:17,650 [myid:1] - INFO  [/127.0.0.1:11227:QuorumCnxManager$Listener@638] - Received connection request /127.0.0.1:43290
2016-08-24 19:20:17,653 [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-08-24 19:20:17,654 [myid:0] - INFO  [WorkerSender[myid=0]:QuorumCnxManager@276] - Have smaller server identifier, so dropping the connection: (1, 0)
2016-08-24 19:20:17,657 [myid:2] - INFO  [/127.0.0.1:11230:QuorumCnxManager$Listener@638] - Received connection request /127.0.0.1:52198
2016-08-24 19:20:17,657 [myid:1] - INFO  [WorkerSender[myid=1]:QuorumCnxManager@276] - Have smaller server identifier, so dropping the connection: (2, 1)
2016-08-24 19:20:17,659 [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-08-24 19:20:17,659 [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-08-24 19:20:17,659 [myid:2] - INFO  [WorkerReceiver[myid=2]: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-08-24 19:20:17,679 [myid:2] - WARN  [SendWorker:1:QuorumCnxManager$SendWorker@841] - Send worker leaving thread  id 1 my id = 2
2016-08-24 19:20:17,680 [myid:2] - WARN  [RecvWorker:1:QuorumCnxManager$RecvWorker@918] - Interrupting SendWorker
2016-08-24 19:20:17,681 [myid:1] - INFO  [/127.0.0.1:11227:QuorumCnxManager$Listener@638] - Received connection request /127.0.0.1:43291
2016-08-24 19:20:17,683 [myid:0] - INFO  [/127.0.0.1:11224:QuorumCnxManager$Listener@638] - Received connection request /127.0.0.1:45377
2016-08-24 19:20:17,683 [myid:1] - 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-08-24 19:20:17,684 [myid:1] - WARN  [SendWorker:0:QuorumCnxManager$SendWorker@841] - Send worker leaving thread  id 0 my id = 1
2016-08-24 19:20:17,686 [myid:1] - WARN  [RecvWorker:0:QuorumCnxManager$RecvWorker@915] - Connection broken for id 0, 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-08-24 19:20:17,686 [myid:1] - WARN  [RecvWorker:0:QuorumCnxManager$RecvWorker@918] - Interrupting SendWorker
2016-08-24 19:20:17,687 [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-08-24 19:20:17,687 [myid:0] - WARN  [RecvWorker:1:QuorumCnxManager$RecvWorker@915] - Connection broken for id 1, my id = 0, 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-08-24 19:20:17,699 [myid:0] - WARN  [RecvWorker:1:QuorumCnxManager$RecvWorker@918] - Interrupting SendWorker
2016-08-24 19:20:17,696 [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-08-24 19:20:17,701 [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-08-24 19:20:17,702 [myid:0] - WARN  [SendWorker:1:QuorumCnxManager$SendWorker@837] - Exception when using channel: for id 1 my id = 0 error = java.net.SocketException: Broken pipe
2016-08-24 19:20:17,688 [myid:1] - WARN  [SendWorker:2:QuorumCnxManager$SendWorker@837] - Exception when using channel: for id 2 my id = 1 error = java.net.SocketException: Broken pipe
2016-08-24 19:20:17,701 [myid:1] - WARN  [RecvWorker:2:QuorumCnxManager$RecvWorker@915] - Connection broken for id 2, my id = 1, 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-08-24 19:20:17,703 [myid:1] - WARN  [RecvWorker:2:QuorumCnxManager$RecvWorker@918] - Interrupting SendWorker
2016-08-24 19:20:17,689 [myid:1] - INFO  [/127.0.0.1:11227:QuorumCnxManager$Listener@638] - Received connection request /127.0.0.1:43293
2016-08-24 19:20:17,708 [myid:1] - WARN  [SendWorker:2:QuorumCnxManager$SendWorker@841] - Send worker leaving thread  id 2 my id = 1
2016-08-24 19:20:17,708 [myid:0] - WARN  [SendWorker:1:QuorumCnxManager$SendWorker@841] - Send worker leaving thread  id 1 my id = 0
2016-08-24 19:20:17,710 [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-08-24 19:20:17,710 [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-08-24 19:20:17,720 [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-08-24 19:20:17,722 [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-08-24 19:20:17,728 [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-08-24 19:20:17,728 [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-08-24 19:20:17,729 [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-08-24 19:20:17,819 [myid:] - INFO  [Time-limited test:FourLetterWordMain@85] - connecting to 127.0.0.1 11222
2016-08-24 19:20:17,820 [myid:0] - INFO  [NIOServerCxnFactory.AcceptThread:/127.0.0.1:11222:NIOServerCnxnFactory$AcceptThread@296] - Accepted socket connection from /127.0.0.1:41114
2016-08-24 19:20:17,822 [myid:0] - INFO  [NIOWorkerThread-2:NIOServerCnxn@485] - Processing stat command from /127.0.0.1:41114
2016-08-24 19:20:17,822 [myid:0] - INFO  [NIOWorkerThread-2:NIOServerCnxn@607] - Closed socket connection for client /127.0.0.1:41114 (no session established for client)
2016-08-24 19:20:17,923 [myid:1] - INFO  [QuorumPeer[myid=1](plain=/127.0.0.1:11225)(secure=disabled):MBeanRegistry@128] - Unregister MBean [org.apache.ZooKeeperService:name0=ReplicatedServer_id1,name1=replica.1,name2=LeaderElection]
2016-08-24 19:20:17,923 [myid:1] - INFO  [QuorumPeer[myid=1](plain=/127.0.0.1:11225)(secure=disabled):QuorumPeer@1109] - FOLLOWING
2016-08-24 19:20:17,928 [myid:2] - INFO  [QuorumPeer[myid=2](plain=/127.0.0.1:11228)(secure=disabled):MBeanRegistry@128] - Unregister MBean [org.apache.ZooKeeperService:name0=ReplicatedServer_id2,name1=replica.2,name2=LeaderElection]
2016-08-24 19:20:17,929 [myid:2] - INFO  [QuorumPeer[myid=2](plain=/127.0.0.1:11228)(secure=disabled):QuorumPeer@1121] - LEADING
2016-08-24 19:20:17,929 [myid:0] - INFO  [QuorumPeer[myid=0](plain=/127.0.0.1:11222)(secure=disabled):MBeanRegistry@128] - Unregister MBean [org.apache.ZooKeeperService:name0=ReplicatedServer_id0,name1=replica.0,name2=LeaderElection]
2016-08-24 19:20:17,930 [myid:0] - INFO  [QuorumPeer[myid=0](plain=/127.0.0.1:11222)(secure=disabled):QuorumPeer@1109] - FOLLOWING
2016-08-24 19:20:17,932 [myid:1] - INFO  [QuorumPeer[myid=1](plain=/127.0.0.1:11225)(secure=disabled):Learner@88] - TCP NoDelay set to: true
2016-08-24 19:20:17,937 [myid:2] - INFO  [QuorumPeer[myid=2](plain=/127.0.0.1:11228)(secure=disabled):Leader@63] - TCP NoDelay set to: true
2016-08-24 19:20:17,937 [myid:2] - INFO  [QuorumPeer[myid=2](plain=/127.0.0.1:11228)(secure=disabled):Leader@83] - zookeeper.leader.maxConcurrentSnapshots = 10
2016-08-24 19:20:17,938 [myid:2] - INFO  [QuorumPeer[myid=2](plain=/127.0.0.1:11228)(secure=disabled):Leader@85] - zookeeper.leader.maxConcurrentSnapshotTimeout = 5
2016-08-24 19:20:17,942 [myid:0] - INFO  [QuorumPeer[myid=0](plain=/127.0.0.1:11222)(secure=disabled):Environment@109] - Server environment:zookeeper.version=3.6.0-SNAPSHOT-1757568, built on 08/24/2016 19:17 GMT
2016-08-24 19:20:17,942 [myid:0] - INFO  [QuorumPeer[myid=0](plain=/127.0.0.1:11222)(secure=disabled):Environment@109] - Server environment:host.name=asf907.gq1.ygridcore.net
2016-08-24 19:20:17,942 [myid:0] - INFO  [QuorumPeer[myid=0](plain=/127.0.0.1:11222)(secure=disabled):Environment@109] - Server environment:java.version=1.7.0_80
2016-08-24 19:20:17,943 [myid:0] - INFO  [QuorumPeer[myid=0](plain=/127.0.0.1:11222)(secure=disabled):Environment@109] - Server environment:java.vendor=Oracle Corporation
2016-08-24 19:20:17,943 [myid:0] - INFO  [QuorumPeer[myid=0](plain=/127.0.0.1:11222)(secure=disabled):Environment@109] - Server environment:java.home=/usr/local/asfpackages/java/jdk1.7.0_80/jre
2016-08-24 19:20:17,943 [myid:0] - INFO  [QuorumPeer[myid=0](plain=/127.0.0.1:11222)(secure=disabled):Environment@109] - Server environment:java.class.path=/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/test/classes:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/test/lib/antlr-2.7.7.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/test/lib/antlr4-runtime-4.5.1-1.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/test/lib/checkstyle-6.13.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/test/lib/commons-beanutils-1.9.2.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/test/lib/commons-cli-1.3.1.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/test/lib/commons-collections-3.2.2.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/test/lib/commons-lang3-3.4.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/test/lib/commons-logging-1.1.1.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/test/lib/guava-18.0.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/test/lib/hamcrest-core-1.3.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/test/lib/junit-4.12.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/test/lib/mockito-all-1.8.2.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/classes:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/src/java/lib/ivy-2.4.0.jar:/home/jenkins/tools/ant/latest/lib/ant.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/lib/commons-cli-1.2.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/lib/jackson-core-asl-1.9.11.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/lib/jackson-mapper-asl-1.9.11.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/lib/javacc.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/lib/jetty-6.1.26.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/lib/jetty-util-6.1.26.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/lib/jline-2.11.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/lib/log4j-1.2.17.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/lib/netty-3.10.5.Final.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/lib/servlet-api-2.5-20081211.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/lib/slf4j-api-1.7.5.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/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-08-24 19:20:17,943 [myid:0] - INFO  [QuorumPeer[myid=0](plain=/127.0.0.1:11222)(secure=disabled):Environment@109] - Server environment:java.library.path=/usr/java/packages/lib/amd64:/usr/lib64:/lib64:/lib:/usr/lib
2016-08-24 19:20:17,943 [myid:0] - INFO  [QuorumPeer[myid=0](plain=/127.0.0.1:11222)(secure=disabled):Environment@109] - Server environment:java.io.tmpdir=/tmp
2016-08-24 19:20:17,943 [myid:0] - INFO  [QuorumPeer[myid=0](plain=/127.0.0.1:11222)(secure=disabled):Environment@109] - Server environment:java.compiler=<NA>
2016-08-24 19:20:17,943 [myid:0] - INFO  [QuorumPeer[myid=0](plain=/127.0.0.1:11222)(secure=disabled):Environment@109] - Server environment:os.name=Linux
2016-08-24 19:20:17,943 [myid:0] - INFO  [QuorumPeer[myid=0](plain=/127.0.0.1:11222)(secure=disabled):Environment@109] - Server environment:os.arch=amd64
2016-08-24 19:20:17,944 [myid:0] - INFO  [QuorumPeer[myid=0](plain=/127.0.0.1:11222)(secure=disabled):Environment@109] - Server environment:os.version=3.13.0-36-lowlatency
2016-08-24 19:20:17,944 [myid:0] - INFO  [QuorumPeer[myid=0](plain=/127.0.0.1:11222)(secure=disabled):Environment@109] - Server environment:user.name=jenkins
2016-08-24 19:20:17,944 [myid:0] - INFO  [QuorumPeer[myid=0](plain=/127.0.0.1:11222)(secure=disabled):Environment@109] - Server environment:user.home=/home/jenkins
2016-08-24 19:20:17,944 [myid:0] - INFO  [QuorumPeer[myid=0](plain=/127.0.0.1:11222)(secure=disabled):Environment@109] - Server environment:user.dir=/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/test
2016-08-24 19:20:17,944 [myid:0] - INFO  [QuorumPeer[myid=0](plain=/127.0.0.1:11222)(secure=disabled):Environment@109] - Server environment:os.memory.free=369MB
2016-08-24 19:20:17,944 [myid:0] - INFO  [QuorumPeer[myid=0](plain=/127.0.0.1:11222)(secure=disabled):Environment@109] - Server environment:os.memory.max=491MB
2016-08-24 19:20:17,944 [myid:0] - INFO  [QuorumPeer[myid=0](plain=/127.0.0.1:11222)(secure=disabled):Environment@109] - Server environment:os.memory.total=491MB
2016-08-24 19:20:17,946 [myid:2] - INFO  [QuorumPeer[myid=2](plain=/127.0.0.1:11228)(secure=disabled):ZooKeeperServer@889] - minSessionTimeout set to 8000
2016-08-24 19:20:17,946 [myid:1] - INFO  [QuorumPeer[myid=1](plain=/127.0.0.1:11225)(secure=disabled):ZooKeeperServer@889] - minSessionTimeout set to 8000
2016-08-24 19:20:17,946 [myid:0] - INFO  [QuorumPeer[myid=0](plain=/127.0.0.1:11222)(secure=disabled):ZooKeeperServer@889] - minSessionTimeout set to 8000
2016-08-24 19:20:17,946 [myid:1] - INFO  [QuorumPeer[myid=1](plain=/127.0.0.1:11225)(secure=disabled):ZooKeeperServer@898] - maxSessionTimeout set to 80000
2016-08-24 19:20:17,948 [myid:1] - INFO  [QuorumPeer[myid=1](plain=/127.0.0.1:11225)(secure=disabled):ZooKeeperServer@159] - Created server with tickTime 4000 minSessionTimeout 8000 maxSessionTimeout 80000 datadir /home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/test/tmp/test7260737707555606353.junit.dir/data/version-2 snapdir /home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/test/tmp/test7260737707555606353.junit.dir/data/version-2
2016-08-24 19:20:17,948 [myid:1] - INFO  [QuorumPeer[myid=1](plain=/127.0.0.1:11225)(secure=disabled):Follower@66] - FOLLOWING - LEADER ELECTION TOOK - 25 MS
2016-08-24 19:20:17,946 [myid:2] - INFO  [QuorumPeer[myid=2](plain=/127.0.0.1:11228)(secure=disabled):ZooKeeperServer@898] - maxSessionTimeout set to 80000
2016-08-24 19:20:17,947 [myid:0] - INFO  [QuorumPeer[myid=0](plain=/127.0.0.1:11222)(secure=disabled):ZooKeeperServer@898] - maxSessionTimeout set to 80000
2016-08-24 19:20:17,953 [myid:2] - INFO  [QuorumPeer[myid=2](plain=/127.0.0.1:11228)(secure=disabled):ZooKeeperServer@159] - Created server with tickTime 4000 minSessionTimeout 8000 maxSessionTimeout 80000 datadir /home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/test/tmp/test1038022970424066351.junit.dir/data/version-2 snapdir /home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/test/tmp/test1038022970424066351.junit.dir/data/version-2
2016-08-24 19:20:17,953 [myid:0] - INFO  [QuorumPeer[myid=0](plain=/127.0.0.1:11222)(secure=disabled):ZooKeeperServer@159] - Created server with tickTime 4000 minSessionTimeout 8000 maxSessionTimeout 80000 datadir /home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/test/tmp/test7330020881446886387.junit.dir/data/version-2 snapdir /home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/test/tmp/test7330020881446886387.junit.dir/data/version-2
2016-08-24 19:20:17,953 [myid:0] - INFO  [QuorumPeer[myid=0](plain=/127.0.0.1:11222)(secure=disabled):Follower@66] - FOLLOWING - LEADER ELECTION TOOK - 23 MS
2016-08-24 19:20:17,953 [myid:1] - WARN  [QuorumPeer[myid=1](plain=/127.0.0.1:11225)(secure=disabled):Learner@273] - Unexpected exception, tries=0, remaining init limit=40000, connecting to /127.0.0.1:11229
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.Learner.sockConnect(Learner.java:227)
	at org.apache.zookeeper.server.quorum.Learner.connectToLeader(Learner.java:256)
	at org.apache.zookeeper.server.quorum.Follower.followLeader(Follower.java:74)
	at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:1111)
2016-08-24 19:20:17,954 [myid:0] - WARN  [QuorumPeer[myid=0](plain=/127.0.0.1:11222)(secure=disabled):Learner@273] - Unexpected exception, tries=0, remaining init limit=40000, connecting to /127.0.0.1:11229
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.Learner.sockConnect(Learner.java:227)
	at org.apache.zookeeper.server.quorum.Learner.connectToLeader(Learner.java:256)
	at org.apache.zookeeper.server.quorum.Follower.followLeader(Follower.java:74)
	at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:1111)
2016-08-24 19:20:17,956 [myid:2] - INFO  [QuorumPeer[myid=2](plain=/127.0.0.1:11228)(secure=disabled):Leader@412] - LEADING - LEADER ELECTION TOOK - 27 MS
2016-08-24 19:20:17,960 [myid:2] - INFO  [QuorumPeer[myid=2](plain=/127.0.0.1:11228)(secure=disabled):FileTxnSnapLog@298] - Snapshotting: 0x0 to /home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/test/tmp/test1038022970424066351.junit.dir/data/version-2/snapshot.0
2016-08-24 19:20:18,073 [myid:] - INFO  [Time-limited test:FourLetterWordMain@85] - connecting to 127.0.0.1 11222
2016-08-24 19:20:18,075 [myid:0] - INFO  [NIOServerCxnFactory.AcceptThread:/127.0.0.1:11222:NIOServerCnxnFactory$AcceptThread@296] - Accepted socket connection from /127.0.0.1:41147
2016-08-24 19:20:18,080 [myid:0] - INFO  [NIOWorkerThread-3:NIOServerCnxn@485] - Processing stat command from /127.0.0.1:41147
2016-08-24 19:20:18,080 [myid:0] - INFO  [NIOWorkerThread-3:NIOServerCnxn@607] - Closed socket connection for client /127.0.0.1:41147 (no session established for client)
2016-08-24 19:20:18,332 [myid:] - INFO  [Time-limited test:FourLetterWordMain@85] - connecting to 127.0.0.1 11222
2016-08-24 19:20:18,333 [myid:0] - INFO  [NIOServerCxnFactory.AcceptThread:/127.0.0.1:11222:NIOServerCnxnFactory$AcceptThread@296] - Accepted socket connection from /127.0.0.1:41177
2016-08-24 19:20:18,334 [myid:0] - INFO  [NIOWorkerThread-4:NIOServerCnxn@485] - Processing stat command from /127.0.0.1:41177
2016-08-24 19:20:18,335 [myid:0] - INFO  [NIOWorkerThread-4:NIOServerCnxn@607] - Closed socket connection for client /127.0.0.1:41177 (no session established for client)
2016-08-24 19:20:18,585 [myid:] - INFO  [Time-limited test:FourLetterWordMain@85] - connecting to 127.0.0.1 11222
2016-08-24 19:20:18,586 [myid:0] - INFO  [NIOServerCxnFactory.AcceptThread:/127.0.0.1:11222:NIOServerCnxnFactory$AcceptThread@296] - Accepted socket connection from /127.0.0.1:41205
2016-08-24 19:20:18,587 [myid:0] - INFO  [NIOWorkerThread-5:NIOServerCnxn@485] - Processing stat command from /127.0.0.1:41205
2016-08-24 19:20:18,588 [myid:0] - INFO  [NIOWorkerThread-5:NIOServerCnxn@607] - Closed socket connection for client /127.0.0.1:41205 (no session established for client)
2016-08-24 19:20:18,838 [myid:] - INFO  [Time-limited test:FourLetterWordMain@85] - connecting to 127.0.0.1 11222
2016-08-24 19:20:18,840 [myid:0] - INFO  [NIOServerCxnFactory.AcceptThread:/127.0.0.1:11222:NIOServerCnxnFactory$AcceptThread@296] - Accepted socket connection from /127.0.0.1:41223
2016-08-24 19:20:18,865 [myid:0] - INFO  [NIOWorkerThread-6:NIOServerCnxn@485] - Processing stat command from /127.0.0.1:41223
2016-08-24 19:20:18,865 [myid:0] - INFO  [NIOWorkerThread-6:NIOServerCnxn@607] - Closed socket connection for client /127.0.0.1:41223 (no session established for client)
2016-08-24 19:20:18,965 [myid:2] - INFO  [LearnerHandler-/127.0.0.1:40597:LearnerHandler@382] - Follower sid: 1 : info : 127.0.0.1:11226:11227:participant;127.0.0.1:11225
2016-08-24 19:20:18,965 [myid:2] - INFO  [LearnerHandler-/127.0.0.1:40598:LearnerHandler@382] - Follower sid: 0 : info : 127.0.0.1:11223:11224:participant;127.0.0.1:11222
2016-08-24 19:20:18,972 [myid:2] - INFO  [LearnerHandler-/127.0.0.1:40598:LearnerHandler@683] - Synchronizing with Follower sid: 0 maxCommittedLog=0x0 minCommittedLog=0x0 lastProcessedZxid=0x0 peerLastZxid=0x0
2016-08-24 19:20:18,972 [myid:2] - INFO  [LearnerHandler-/127.0.0.1:40597:LearnerHandler@683] - Synchronizing with Follower sid: 1 maxCommittedLog=0x0 minCommittedLog=0x0 lastProcessedZxid=0x0 peerLastZxid=0x0
2016-08-24 19:20:18,972 [myid:2] - INFO  [LearnerHandler-/127.0.0.1:40598:LearnerHandler@727] - Sending DIFF zxid=0x0 for peer sid: 0
2016-08-24 19:20:18,972 [myid:2] - INFO  [LearnerHandler-/127.0.0.1:40597:LearnerHandler@727] - Sending DIFF zxid=0x0 for peer sid: 1
2016-08-24 19:20:18,974 [myid:0] - INFO  [QuorumPeer[myid=0](plain=/127.0.0.1:11222)(secure=disabled):Learner@366] - Getting a diff from the leader 0x0
2016-08-24 19:20:18,974 [myid:1] - INFO  [QuorumPeer[myid=1](plain=/127.0.0.1:11225)(secure=disabled):Learner@366] - Getting a diff from the leader 0x0
2016-08-24 19:20:18,978 [myid:0] - INFO  [QuorumPeer[myid=0](plain=/127.0.0.1:11222)(secure=disabled):Learner@509] - Learner received NEWLEADER message
2016-08-24 19:20:18,978 [myid:1] - INFO  [QuorumPeer[myid=1](plain=/127.0.0.1:11225)(secure=disabled):Learner@509] - Learner received NEWLEADER message
2016-08-24 19:20:18,980 [myid:0] - INFO  [QuorumPeer[myid=0](plain=/127.0.0.1:11222)(secure=disabled):FileTxnSnapLog@298] - Snapshotting: 0x0 to /home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/test/tmp/test7330020881446886387.junit.dir/data/version-2/snapshot.0
2016-08-24 19:20:18,981 [myid:1] - INFO  [QuorumPeer[myid=1](plain=/127.0.0.1:11225)(secure=disabled):FileTxnSnapLog@298] - Snapshotting: 0x0 to /home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/test/tmp/test7260737707555606353.junit.dir/data/version-2/snapshot.0
2016-08-24 19:20:18,982 [myid:2] - INFO  [QuorumPeer[myid=2](plain=/127.0.0.1:11228)(secure=disabled):Leader@1255] - Have quorum of supporters, sids: [ [0, 2],[0, 2] ]; starting up and setting last processed zxid: 0x100000000
2016-08-24 19:20:19,012 [myid:2] - INFO  [QuorumPeer[myid=2](plain=/127.0.0.1:11228)(secure=disabled):CommitProcessor@318] - Configuring CommitProcessor with 16 worker threads.
2016-08-24 19:20:19,056 [myid:2] - INFO  [QuorumPeer[myid=2](plain=/127.0.0.1:11228)(secure=disabled):ContainerManager@64] - Using checkIntervalMs=60000 maxPerMinute=10000
2016-08-24 19:20:19,062 [myid:1] - INFO  [QuorumPeer[myid=1](plain=/127.0.0.1:11225)(secure=disabled):Learner@493] - Learner received UPTODATE message
2016-08-24 19:20:19,062 [myid:0] - INFO  [QuorumPeer[myid=0](plain=/127.0.0.1:11222)(secure=disabled):Learner@493] - Learner received UPTODATE message
2016-08-24 19:20:19,067 [myid:0] - INFO  [QuorumPeer[myid=0](plain=/127.0.0.1:11222)(secure=disabled):CommitProcessor@318] - Configuring CommitProcessor with 16 worker threads.
2016-08-24 19:20:19,080 [myid:1] - INFO  [QuorumPeer[myid=1](plain=/127.0.0.1:11225)(secure=disabled):CommitProcessor@318] - Configuring CommitProcessor with 16 worker threads.
2016-08-24 19:20:19,116 [myid:] - INFO  [Time-limited test:FourLetterWordMain@85] - connecting to 127.0.0.1 11222
2016-08-24 19:20:19,117 [myid:0] - INFO  [NIOServerCxnFactory.AcceptThread:/127.0.0.1:11222:NIOServerCnxnFactory$AcceptThread@296] - Accepted socket connection from /127.0.0.1:41246
2016-08-24 19:20:19,120 [myid:0] - INFO  [NIOWorkerThread-7:NIOServerCnxn@485] - Processing stat command from /127.0.0.1:41246
2016-08-24 19:20:19,122 [myid:0] - INFO  [NIOWorkerThread-7:StatCommand@49] - Stat command output
2016-08-24 19:20:19,123 [myid:0] - INFO  [NIOWorkerThread-7:NIOServerCnxn@607] - Closed socket connection for client /127.0.0.1:41246 (no session established for client)
2016-08-24 19:20:19,123 [myid:] - INFO  [Time-limited test:FourLetterWordMain@85] - connecting to 127.0.0.1 11225
2016-08-24 19:20:19,124 [myid:1] - INFO  [NIOServerCxnFactory.AcceptThread:/127.0.0.1:11225:NIOServerCnxnFactory$AcceptThread@296] - Accepted socket connection from /127.0.0.1:55153
2016-08-24 19:20:19,125 [myid:1] - INFO  [NIOWorkerThread-1:NIOServerCnxn@485] - Processing stat command from /127.0.0.1:55153
2016-08-24 19:20:19,125 [myid:1] - INFO  [NIOWorkerThread-1:StatCommand@49] - Stat command output
2016-08-24 19:20:19,126 [myid:1] - INFO  [NIOWorkerThread-1:NIOServerCnxn@607] - Closed socket connection for client /127.0.0.1:55153 (no session established for client)
2016-08-24 19:20:19,126 [myid:] - INFO  [Time-limited test:FourLetterWordMain@85] - connecting to 127.0.0.1 11228
2016-08-24 19:20:19,127 [myid:2] - INFO  [NIOServerCxnFactory.AcceptThread:/127.0.0.1:11228:NIOServerCnxnFactory$AcceptThread@296] - Accepted socket connection from /127.0.0.1:59066
2016-08-24 19:20:19,130 [myid:2] - INFO  [NIOWorkerThread-1:NIOServerCnxn@485] - Processing stat command from /127.0.0.1:59066
2016-08-24 19:20:19,131 [myid:2] - INFO  [NIOWorkerThread-1:StatCommand@49] - Stat command output
2016-08-24 19:20:19,131 [myid:2] - INFO  [NIOWorkerThread-1:NIOServerCnxn@607] - Closed socket connection for client /127.0.0.1:59066 (no session established for client)
2016-08-24 19:20:19,138 [myid:] - INFO  [Time-limited test:Environment@109] - Client environment:zookeeper.version=3.6.0-SNAPSHOT-1757568, built on 08/24/2016 19:17 GMT
2016-08-24 19:20:19,138 [myid:] - INFO  [Time-limited test:Environment@109] - Client environment:host.name=asf907.gq1.ygridcore.net
2016-08-24 19:20:19,138 [myid:] - INFO  [Time-limited test:Environment@109] - Client environment:java.version=1.7.0_80
2016-08-24 19:20:19,139 [myid:] - INFO  [Time-limited test:Environment@109] - Client environment:java.vendor=Oracle Corporation
2016-08-24 19:20:19,139 [myid:] - INFO  [Time-limited test:Environment@109] - Client environment:java.home=/usr/local/asfpackages/java/jdk1.7.0_80/jre
2016-08-24 19:20:19,139 [myid:] - INFO  [Time-limited test:Environment@109] - Client environment:java.class.path=/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/test/classes:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/test/lib/antlr-2.7.7.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/test/lib/antlr4-runtime-4.5.1-1.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/test/lib/checkstyle-6.13.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/test/lib/commons-beanutils-1.9.2.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/test/lib/commons-cli-1.3.1.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/test/lib/commons-collections-3.2.2.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/test/lib/commons-lang3-3.4.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/test/lib/commons-logging-1.1.1.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/test/lib/guava-18.0.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/test/lib/hamcrest-core-1.3.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/test/lib/junit-4.12.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/test/lib/mockito-all-1.8.2.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/classes:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/src/java/lib/ivy-2.4.0.jar:/home/jenkins/tools/ant/latest/lib/ant.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/lib/commons-cli-1.2.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/lib/jackson-core-asl-1.9.11.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/lib/jackson-mapper-asl-1.9.11.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/lib/javacc.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/lib/jetty-6.1.26.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/lib/jetty-util-6.1.26.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/lib/jline-2.11.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/lib/log4j-1.2.17.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/lib/netty-3.10.5.Final.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/lib/servlet-api-2.5-20081211.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/lib/slf4j-api-1.7.5.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/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-08-24 19:20:19,139 [myid:] - INFO  [Time-limited test:Environment@109] - Client environment:java.library.path=/usr/java/packages/lib/amd64:/usr/lib64:/lib64:/lib:/usr/lib
2016-08-24 19:20:19,140 [myid:] - INFO  [Time-limited test:Environment@109] - Client environment:java.io.tmpdir=/tmp
2016-08-24 19:20:19,140 [myid:] - INFO  [Time-limited test:Environment@109] - Client environment:java.compiler=<NA>
2016-08-24 19:20:19,140 [myid:] - INFO  [Time-limited test:Environment@109] - Client environment:os.name=Linux
2016-08-24 19:20:19,140 [myid:] - INFO  [Time-limited test:Environment@109] - Client environment:os.arch=amd64
2016-08-24 19:20:19,141 [myid:] - INFO  [Time-limited test:Environment@109] - Client environment:os.version=3.13.0-36-lowlatency
2016-08-24 19:20:19,141 [myid:] - INFO  [Time-limited test:Environment@109] - Client environment:user.name=jenkins
2016-08-24 19:20:19,141 [myid:] - INFO  [Time-limited test:Environment@109] - Client environment:user.home=/home/jenkins
2016-08-24 19:20:19,141 [myid:] - INFO  [Time-limited test:Environment@109] - Client environment:user.dir=/home/jenkins/jenkins-slave/workspace/ZooKeeper-trunk/trunk/build/test
2016-08-24 19:20:19,141 [myid:] - INFO  [Time-limited test:Environment@109] - Client environment:os.memory.free=462MB
2016-08-24 19:20:19,142 [myid:] - INFO  [Time-limited test:Environment@109] - Client environment:os.memory.max=491MB
2016-08-24 19:20:19,142 [myid:] - INFO  [Time-limited test:Environment@109] - Client environment:os.memory.total=491MB
2016-08-24 19:20:19,145 [myid:] - INFO  [Time-limited test:ZooKeeper@855] - Initiating client connection, connectString=127.0.0.1:11222 sessionTimeout=30000 watcher=org.apache.zookeeper.test.ClientBase$CountdownWatcher@2b6c7d59
2016-08-24 19:20:19,169 [myid:127.0.0.1:11222] - INFO  [Time-limited test-SendThread(127.0.0.1:11222):ClientCnxn$SendThread@1113] - Opening socket connection to server 127.0.0.1/127.0.0.1:11222. Will not attempt to authenticate using SASL (unknown error)
2016-08-24 19:20:19,172 [myid:0] - INFO  [NIOServerCxnFactory.AcceptThread:/127.0.0.1:11222:NIOServerCnxnFactory$AcceptThread@296] - Accepted socket connection from /127.0.0.1:41255
2016-08-24 19:20:19,177 [myid:127.0.0.1:11222] - INFO  [Time-limited test-SendThread(127.0.0.1:11222):ClientCnxn$SendThread@948] - Socket connection established, initiating session, client: /127.0.0.1:41255, server: 127.0.0.1/127.0.0.1:11222
2016-08-24 19:20:19,201 [myid:0] - INFO  [NIOWorkerThread-8:ZooKeeperServer@995] - Client attempting to establish new session at /127.0.0.1:41255
2016-08-24 19:20:19,206 [myid:2] - INFO  [SyncThread:2:FileTxnLog@204] - Creating new log file: log.100000001
2016-08-24 19:20:19,206 [myid:0] - WARN  [QuorumPeer[myid=0](plain=/127.0.0.1:11222)(secure=disabled):Follower@122] - Got zxid 0x100000001 expected 0x1
2016-08-24 19:20:19,206 [myid:1] - WARN  [QuorumPeer[myid=1](plain=/127.0.0.1:11225)(secure=disabled):Follower@122] - Got zxid 0x100000001 expected 0x1
2016-08-24 19:20:19,207 [myid:0] - INFO  [SyncThread:0:FileTxnLog@204] - Creating new log file: log.100000001
2016-08-24 19:20:19,207 [myid:1] - INFO  [SyncThread:1:FileTxnLog@204] - Creating new log file: log.100000001
2016-08-24 19:20:19,229 [myid:0] - INFO  [CommitProcWorkThread-1:ZooKeeperServer@709] - Established session 0x2162abf710000 with negotiated timeout 30000 for client /127.0.0.1:41255
2016-08-24 19:20:19,231 [myid:127.0.0.1:11222] - INFO  [Time-limited test-SendThread(127.0.0.1:11222):ClientCnxn$SendThread@1381] - Session establishment complete on server 127.0.0.1/127.0.0.1:11222, sessionid = 0x2162abf710000, negotiated timeout = 30000
2016-08-24 19:20:19,251 [myid:2] - INFO  [SyncThread:2:FileTxnLog@204] - Creating new log file: log.100000003
2016-08-24 19:20:19,251 [myid:2] - ERROR [SyncThread:2:ZooKeeperCriticalThread@48] - Severe unrecoverable error, from thread : SyncThread:2
java.io.IOException: Input/output error
	at org.apache.zookeeper.test.NonRecoverableErrorTest$1.commit(NonRecoverableErrorTest.java:101)
	at org.apache.zookeeper.server.ZKDatabase.commit(ZKDatabase.java:557)
	at org.apache.zookeeper.server.SyncRequestProcessor.flush(SyncRequestProcessor.java:178)
	at org.apache.zookeeper.server.SyncRequestProcessor.run(SyncRequestProcessor.java:113)
2016-08-24 19:20:19,251 [myid:2] - INFO  [SyncThread:2:ZooKeeperServerListenerImpl@42] - Thread SyncThread:2 exits, error code 1
2016-08-24 19:20:19,252 [myid:2] - INFO  [SyncThread:2:SyncRequestProcessor@169] - SyncRequestProcessor exited!
2016-08-24 19:20:19,253 [myid:] - INFO  [Time-limited test:JUnit4ZKTestRunner$LoggedInvokeMethod@98] - TEST METHOD FAILED testZooKeeperServiceAvailableOnLeader
java.lang.AssertionError: IOException is expected due to error injected to transaction log commit
	at org.junit.Assert.fail(Assert.java:88)
	at org.apache.zookeeper.test.NonRecoverableErrorTest.testZooKeeperServiceAvailableOnLeader(NonRecoverableErrorTest.java:115)
	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.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:298)
	at org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:292)
	at java.util.concurrent.FutureTask.run(FutureTask.java:262)
	at java.lang.Thread.run(Thread.java:745)
2016-08-24 19:20:19,254 [myid:] - INFO  [main:ZKTestCase$1@70] - FAILED testZooKeeperServiceAvailableOnLeader
java.lang.AssertionError: IOException is expected due to error injected to transaction log commit
	at org.junit.Assert.fail(Assert.java:88)
	at org.apache.zookeeper.test.NonRecoverableErrorTest.testZooKeeperServiceAvailableOnLeader(NonRecoverableErrorTest.java:115)
	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.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:298)
	at org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:292)
	at java.util.concurrent.FutureTask.run(FutureTask.java:262)
	at java.lang.Thread.run(Thread.java:745)
2016-08-24 19:20:19,255 [myid:] - INFO  [main:ZKTestCase$1@60] - FINISHED testZooKeeperServiceAvailableOnLeader

Attachments

Issue Links

is related to

ZOOKEEPER-2247 Zookeeper service becomes unavailable when leader fails to write transaction log

Closed

relates to

ZOOKEEPER-2135 fix trunk build

Open

Activity

People

Assignee:: Andor Molnar

Reporter:: Michael Han

Votes:: 0 Vote for this issue

Watchers:: 2 Start watching this issue

Dates

Created:: 25/Aug/16 00:14

Updated:: 25/Oct/18 14:58

Resolved:: 25/Oct/18 14:58