zookeeper-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Andor Molnar (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (ZOOKEEPER-2529) Flaky Test: org.apache.zookeeper.test.NonRecoverableErrorTest.testZooKeeperServiceAvailableOnLeader
Date Thu, 25 Oct 2018 14:59:00 GMT

    [ https://issues.apache.org/jira/browse/ZOOKEEPER-2529?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16663852#comment-16663852 ] 

Andor Molnar commented on ZOOKEEPER-2529:
-----------------------------------------

Verified a bunch of recent builds, test is not failing anymore. Closing.

> Flaky Test: org.apache.zookeeper.test.NonRecoverableErrorTest.testZooKeeperServiceAvailableOnLeader
> ---------------------------------------------------------------------------------------------------
>
>                 Key: ZOOKEEPER-2529
>                 URL: https://issues.apache.org/jira/browse/ZOOKEEPER-2529
>             Project: ZooKeeper
>          Issue Type: Sub-task
>    Affects Versions: 3.4.9, 3.5.3
>            Reporter: Michael Han
>            Priority: Major
>              Labels: flaky, flaky-test
>
> This flaky is introduced by ZOOKEEPER-2247 recently.
> {noformat}
> 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
> {noformat}



--
This message was sent by Atlassian JIRA
(v7.6.3#76005)

Mime
View raw message