[
https://issues.apache.org/jira/browse/ZOOKEEPER-2529?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Andor Molnar updated ZOOKEEPER-2529:
------------------------------------
Parent: ZOOKEEPER-3170
Issue Type: Sub-task (was: Test)
> 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)
