[
https://issues.apache.org/jira/browse/ZOOKEEPER-2502?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15434183#comment-15434183
]
Michael Han commented on ZOOKEEPER-2502:
----------------------------------------
bq. Shouldn't we fix this for all the tests? Why just this one line?
It's because this specific test failed because of the sync limit time with hard
proof... the rest of tests (in same QuorumCnxManagerTest suite at least) passed
under stress, so they were untouched. Though be proactive seems a good idea for
the purpose of consistency and does no harm to slow down the tests (as the sync
limit is upper bound, not lower bound), so I'll update the rest of tests in
same suite with new sync limit time.
bq. Also shouldn't we be fixing this on trunk/3.5 as well?
For this specific test, no need, because it does not exist in 3.5 :) This test
was specifically to test 3.4 upgrade capability for the protocol flag.
I am not aware of any 3.5 tests that's failing because of such configuration
issues, but I will keep this in mind while sweeping rest of the flaky tests.
> Flaky Test:
> org.apache.zookeeper.server.quorum.CnxManagerTest.testCnxFromFutureVersion
> --------------------------------------------------------------------------------------
>
> Key: ZOOKEEPER-2502
> URL: https://issues.apache.org/jira/browse/ZOOKEEPER-2502
> Project: ZooKeeper
> Issue Type: Bug
> Components: tests
> Affects Versions: 3.4.9
> Reporter: Michael Han
> Assignee: Michael Han
> Labels: flaky, flaky-test
> Fix For: 3.4.10
>
> Attachments: ZOOKEEPER-2502.patch, ZOOKEEPER-2502.patch
>
>
> {noformat}
> Error Message
> Broken pipe
> Stacktrace
> java.io.IOException: Broken pipe
> at sun.nio.ch.FileDispatcherImpl.write0(Native Method)
> at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47)
> at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93)
> at sun.nio.ch.IOUtil.write(IOUtil.java:65)
> at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:466)
> at java.nio.channels.Channels.writeFullyImpl(Channels.java:78)
> at java.nio.channels.Channels.writeFully(Channels.java:98)
> at java.nio.channels.Channels.access$000(Channels.java:61)
> at java.nio.channels.Channels$1.write(Channels.java:174)
> at java.io.OutputStream.write(OutputStream.java:75)
> at java.nio.channels.Channels$1.write(Channels.java:155)
> at java.io.DataOutputStream.writeInt(DataOutputStream.java:198)
> at
> org.apache.zookeeper.server.quorum.CnxManagerTest.testCnxFromFutureVersion(CnxManagerTest.java:318)
> at
> org.apache.zookeeper.JUnit4ZKTestRunner$LoggedInvokeMethod.evaluate(JUnit4ZKTestRunner.java:55)
> Standard Output
> 2016-07-12 22:34:46,623 [myid:] - INFO [main:ZKTestCase$1@50] - STARTING
> testCnxFromFutureVersion
> 2016-07-12 22:34:46,627 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11221
> 2016-07-12 22:34:46,630 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11222
> 2016-07-12 22:34:46,631 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11223
> 2016-07-12 22:34:46,643 [myid:] - INFO [main:QuorumPeer$QuorumServer@149] -
> Resolved hostname: 0.0.0.0 to address: /0.0.0.0
> 2016-07-12 22:34:46,658 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11224
> 2016-07-12 22:34:46,658 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11225
> 2016-07-12 22:34:46,659 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11226
> 2016-07-12 22:34:46,659 [myid:] - INFO [main:QuorumPeer$QuorumServer@149] -
> Resolved hostname: 0.0.0.0 to address: /0.0.0.0
> 2016-07-12 22:34:46,659 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11227
> 2016-07-12 22:34:46,659 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11228
> 2016-07-12 22:34:46,659 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11229
> 2016-07-12 22:34:46,660 [myid:] - INFO [main:QuorumPeer$QuorumServer@149] -
> Resolved hostname: 0.0.0.0 to address: /0.0.0.0
> 2016-07-12 22:34:46,660 [myid:] - INFO
> [main:JUnit4ZKTestRunner$LoggedInvokeMethod@53] - RUNNING TEST METHOD
> testCnxFromFutureVersion
> 2016-07-12 22:34:46,672 [myid:] - INFO [main:NIOServerCnxnFactory@89] -
> binding to port 0.0.0.0/0.0.0.0:11225
> 2016-07-12 22:34:46,692 [myid:] - INFO [main:CnxManagerTest@301] - Election
> port: 11226
> 2016-07-12 22:34:46,692 [myid:] - INFO
> [ListenerThread:QuorumCnxManager$Listener@534] - My election bind port:
> /0.0.0.0:11226
> 2016-07-12 22:34:47,696 [myid:] - INFO
> [/0.0.0.0:11226:QuorumCnxManager$Listener@541] - Received connection request
> /140.211.11.27:48724
> 2016-07-12 22:34:49,700 [myid:] - WARN [/0.0.0.0:11226:QuorumCnxManager@274]
> - Exception reading or writing challenge: java.net.SocketTimeoutException:
> Read timed out
> 2016-07-12 22:34:52,700 [myid:] - INFO
> [main:JUnit4ZKTestRunner$LoggedInvokeMethod@74] - TEST METHOD FAILED
> testCnxFromFutureVersion
> java.io.IOException: Broken pipe
> at sun.nio.ch.FileDispatcherImpl.write0(Native Method)
> at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47)
> at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93)
> at sun.nio.ch.IOUtil.write(IOUtil.java:65)
> at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:466)
> at java.nio.channels.Channels.writeFullyImpl(Channels.java:78)
> at java.nio.channels.Channels.writeFully(Channels.java:98)
> at java.nio.channels.Channels.access$000(Channels.java:61)
> at java.nio.channels.Channels$1.write(Channels.java:174)
> at java.io.OutputStream.write(OutputStream.java:75)
> at java.nio.channels.Channels$1.write(Channels.java:155)
> at java.io.DataOutputStream.writeInt(DataOutputStream.java:198)
> at
> org.apache.zookeeper.server.quorum.CnxManagerTest.testCnxFromFutureVersion(CnxManagerTest.java:318)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:483)
> at
> org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:44)
> at
> org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
> at
> org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:41)
> at
> org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:20)
> at
> org.apache.zookeeper.JUnit4ZKTestRunner$LoggedInvokeMethod.evaluate(JUnit4ZKTestRunner.java:55)
> at
> org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28)
> at org.junit.rules.TestWatchman$1.evaluate(TestWatchman.java:48)
> at
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:76)
> at
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50)
> at org.junit.runners.ParentRunner$3.run(ParentRunner.java:193)
> at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:52)
> at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:191)
> at org.junit.runners.ParentRunner.access$000(ParentRunner.java:42)
> at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:184)
> at org.junit.runners.ParentRunner.run(ParentRunner.java:236)
> at junit.framework.JUnit4TestAdapter.run(JUnit4TestAdapter.java:39)
> at
> org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.run(JUnitTestRunner.java:518)
> at
> org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.launch(JUnitTestRunner.java:1052)
> at
> org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.main(JUnitTestRunner.java:906)
> 2016-07-12 22:34:52,705 [myid:] - INFO [main:ZKTestCase$1@65] - FAILED
> testCnxFromFutureVersion
> java.io.IOException: Broken pipe
> at sun.nio.ch.FileDispatcherImpl.write0(Native Method)
> at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47)
> at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93)
> at sun.nio.ch.IOUtil.write(IOUtil.java:65)
> at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:466)
> at java.nio.channels.Channels.writeFullyImpl(Channels.java:78)
> at java.nio.channels.Channels.writeFully(Channels.java:98)
> at java.nio.channels.Channels.access$000(Channels.java:61)
> at java.nio.channels.Channels$1.write(Channels.java:174)
> at java.io.OutputStream.write(OutputStream.java:75)
> at java.nio.channels.Channels$1.write(Channels.java:155)
> at java.io.DataOutputStream.writeInt(DataOutputStream.java:198)
> at
> org.apache.zookeeper.server.quorum.CnxManagerTest.testCnxFromFutureVersion(CnxManagerTest.java:318)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:483)
> at
> org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:44)
> at
> org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
> at
> org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:41)
> at
> org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:20)
> at
> org.apache.zookeeper.JUnit4ZKTestRunner$LoggedInvokeMethod.evaluate(JUnit4ZKTestRunner.java:55)
> at
> org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28)
> at org.junit.rules.TestWatchman$1.evaluate(TestWatchman.java:48)
> at
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:76)
> at
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50)
> at org.junit.runners.ParentRunner$3.run(ParentRunner.java:193)
> at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:52)
> at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:191)
> at org.junit.runners.ParentRunner.access$000(ParentRunner.java:42)
> at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:184)
> at org.junit.runners.ParentRunner.run(ParentRunner.java:236)
> at junit.framework.JUnit4TestAdapter.run(JUnit4TestAdapter.java:39)
> at
> org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.run(JUnitTestRunner.java:518)
> at
> org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.launch(JUnitTestRunner.java:1052)
> at
> org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.main(JUnitTestRunner.java:906)
> 2016-07-12 22:34:52,706 [myid:] - INFO [main:ZKTestCase$1@55] - FINISHED
> testCnxFromFutureVersion
> 2016-07-12 22:34:52,720 [myid:] - INFO [main:ZKTestCase$1@50] - STARTING
> testSocketTimeout
> 2016-07-12 22:34:52,720 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11230
> 2016-07-12 22:34:52,720 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11231
> 2016-07-12 22:34:52,720 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11232
> 2016-07-12 22:34:52,721 [myid:] - INFO [main:QuorumPeer$QuorumServer@149] -
> Resolved hostname: 0.0.0.0 to address: /0.0.0.0
> 2016-07-12 22:34:52,721 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11233
> 2016-07-12 22:34:52,722 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11234
> 2016-07-12 22:34:52,722 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11235
> 2016-07-12 22:34:52,722 [myid:] - INFO [main:QuorumPeer$QuorumServer@149] -
> Resolved hostname: 0.0.0.0 to address: /0.0.0.0
> 2016-07-12 22:34:52,723 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11236
> 2016-07-12 22:34:52,723 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11237
> 2016-07-12 22:34:52,723 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11238
> 2016-07-12 22:34:52,724 [myid:] - INFO [main:QuorumPeer$QuorumServer@149] -
> Resolved hostname: 0.0.0.0 to address: /0.0.0.0
> 2016-07-12 22:34:52,724 [myid:] - INFO
> [main:JUnit4ZKTestRunner$LoggedInvokeMethod@53] - RUNNING TEST METHOD
> testSocketTimeout
> 2016-07-12 22:34:52,725 [myid:] - INFO [main:NIOServerCnxnFactory@89] -
> binding to port 0.0.0.0/0.0.0.0:11234
> 2016-07-12 22:34:52,726 [myid:] - INFO [main:CnxManagerTest@370] - Election
> port: 11235
> 2016-07-12 22:34:52,726 [myid:] - INFO
> [ListenerThread:QuorumCnxManager$Listener@534] - My election bind port:
> /0.0.0.0:11235
> 2016-07-12 22:34:53,729 [myid:] - INFO
> [/0.0.0.0:11235:QuorumCnxManager$Listener@541] - Received connection request
> /140.211.11.27:34496
> 2016-07-12 22:34:57,734 [myid:] - WARN [/0.0.0.0:11235:QuorumCnxManager@274]
> - Exception reading or writing challenge: java.net.SocketTimeoutException:
> Read timed out
> 2016-07-12 22:34:57,734 [myid:] - WARN [main:QuorumCnxManager@274] -
> Exception reading or writing challenge: java.io.EOFException
> 2016-07-12 22:34:57,734 [myid:] - INFO
> [main:JUnit4ZKTestRunner$LoggedInvokeMethod@58] - Memory used 3153
> 2016-07-12 22:34:57,735 [myid:] - INFO
> [main:JUnit4ZKTestRunner$LoggedInvokeMethod@63] - Number of threads 6
> 2016-07-12 22:34:57,735 [myid:] - INFO
> [main:JUnit4ZKTestRunner$LoggedInvokeMethod@78] - FINISHED TEST METHOD
> testSocketTimeout
> 2016-07-12 22:34:57,735 [myid:] - INFO [main:ZKTestCase$1@60] - SUCCEEDED
> testSocketTimeout
> 2016-07-12 22:34:57,735 [myid:] - INFO [main:ZKTestCase$1@55] - FINISHED
> testSocketTimeout
> 2016-07-12 22:34:57,735 [myid:] - INFO [main:ZKTestCase$1@50] - STARTING
> testWorkerThreads
> 2016-07-12 22:34:57,736 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11239
> 2016-07-12 22:34:57,736 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11240
> 2016-07-12 22:34:57,736 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11241
> 2016-07-12 22:34:57,736 [myid:] - INFO [main:QuorumPeer$QuorumServer@149] -
> Resolved hostname: 0.0.0.0 to address: /0.0.0.0
> 2016-07-12 22:34:57,736 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11242
> 2016-07-12 22:34:57,737 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11243
> 2016-07-12 22:34:57,737 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11244
> 2016-07-12 22:34:57,737 [myid:] - INFO [main:QuorumPeer$QuorumServer@149] -
> Resolved hostname: 0.0.0.0 to address: /0.0.0.0
> 2016-07-12 22:34:57,737 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11245
> 2016-07-12 22:34:57,737 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11246
> 2016-07-12 22:34:57,737 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11247
> 2016-07-12 22:34:57,737 [myid:] - INFO [main:QuorumPeer$QuorumServer@149] -
> Resolved hostname: 0.0.0.0 to address: /0.0.0.0
> 2016-07-12 22:34:57,738 [myid:] - INFO
> [main:JUnit4ZKTestRunner$LoggedInvokeMethod@53] - RUNNING TEST METHOD
> testWorkerThreads
> 2016-07-12 22:34:57,738 [myid:] - INFO [main:NIOServerCnxnFactory@89] -
> binding to port 0.0.0.0/0.0.0.0:11240
> 2016-07-12 22:34:57,784 [myid:] - INFO [main:CnxManagerTest@393] - Starting
> peer 0
> 2016-07-12 22:34:57,789 [myid:] - INFO [main:QuorumPeer@533] - currentEpoch
> not found! Creating with a reasonable default of 0. This should only happen
> when you are upgrading your installation
> 2016-07-12 22:34:57,905 [myid:] - INFO [main:QuorumPeer@548] - acceptedEpoch
> not found! Creating with a reasonable default of 0. This should only happen
> when you are upgrading your installation
> 2016-07-12 22:34:57,945 [myid:] - INFO
> [ListenerThread:QuorumCnxManager$Listener@534] - My election bind port:
> /0.0.0.0:11241
> 2016-07-12 22:34:57,953 [myid:] - INFO [main:NIOServerCnxnFactory@89] -
> binding to port 0.0.0.0/0.0.0.0:11243
> 2016-07-12 22:34:57,954 [myid:] - INFO [main:CnxManagerTest@393] - Starting
> peer 1
> 2016-07-12 22:34:57,954 [myid:] - INFO [main:QuorumPeer@533] - currentEpoch
> not found! Creating with a reasonable default of 0. This should only happen
> when you are upgrading your installation
> 2016-07-12 22:34:58,024 [myid:] - INFO
> [QuorumPeer[myid=0]/0:0:0:0:0:0:0:0:11240:QuorumPeer@774] - LOOKING
> 2016-07-12 22:34:58,025 [myid:] - INFO [main:QuorumPeer@548] - acceptedEpoch
> not found! Creating with a reasonable default of 0. This should only happen
> when you are upgrading your installation
> 2016-07-12 22:34:58,025 [myid:] - INFO
> [QuorumPeer[myid=0]/0:0:0:0:0:0:0:0:11240:FastLeaderElection@818] - New
> election. My id = 0, proposed zxid=0x0
> 2016-07-12 22:34:58,028 [myid:] - INFO
> [WorkerReceiver[myid=0]:FastLeaderElection@600] - Notification: 1 (message
> format version), 0 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING
> (n.state), 0 (n.sid), 0x0 (n.peerEpoch) LOOKING (my state)
> 2016-07-12 22:34:58,028 [myid:] - WARN
> [WorkerSender[myid=0]:QuorumCnxManager@400] - Cannot open channel to 1 at
> election address /0.0.0.0:11244
> java.net.ConnectException: Connection refused
> at java.net.PlainSocketImpl.socketConnect(Native Method)
> at
> java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:345)
> at
> java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:204)
> at
> java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
> at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
> at java.net.Socket.connect(Socket.java:589)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.connectOne(QuorumCnxManager.java:381)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.toSend(QuorumCnxManager.java:354)
> at
> org.apache.zookeeper.server.quorum.FastLeaderElection$Messenger$WorkerSender.process(FastLeaderElection.java:452)
> at
> org.apache.zookeeper.server.quorum.FastLeaderElection$Messenger$WorkerSender.run(FastLeaderElection.java:433)
> at java.lang.Thread.run(Thread.java:744)
> 2016-07-12 22:34:58,029 [myid:] - INFO
> [WorkerSender[myid=0]:QuorumPeer$QuorumServer@149] - Resolved hostname:
> 0.0.0.0 to address: /0.0.0.0
> 2016-07-12 22:34:58,030 [myid:] - WARN
> [WorkerSender[myid=0]:QuorumCnxManager@400] - Cannot open channel to 2 at
> election address /0.0.0.0:11247
> java.net.ConnectException: Connection refused
> at java.net.PlainSocketImpl.socketConnect(Native Method)
> at
> java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:345)
> at
> java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:204)
> at
> java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
> at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
> at java.net.Socket.connect(Socket.java:589)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.connectOne(QuorumCnxManager.java:381)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.toSend(QuorumCnxManager.java:354)
> at
> org.apache.zookeeper.server.quorum.FastLeaderElection$Messenger$WorkerSender.process(FastLeaderElection.java:452)
> at
> org.apache.zookeeper.server.quorum.FastLeaderElection$Messenger$WorkerSender.run(FastLeaderElection.java:433)
> at java.lang.Thread.run(Thread.java:744)
> 2016-07-12 22:34:58,030 [myid:] - INFO
> [WorkerSender[myid=0]:QuorumPeer$QuorumServer@149] - Resolved hostname:
> 0.0.0.0 to address: /0.0.0.0
> 2016-07-12 22:34:58,050 [myid:] - INFO
> [ListenerThread:QuorumCnxManager$Listener@534] - My election bind port:
> /0.0.0.0:11244
> 2016-07-12 22:34:58,052 [myid:] - INFO [main:NIOServerCnxnFactory@89] -
> binding to port 0.0.0.0/0.0.0.0:11246
> 2016-07-12 22:34:58,052 [myid:] - INFO [main:CnxManagerTest@393] - Starting
> peer 2
> 2016-07-12 22:34:58,053 [myid:] - INFO [main:QuorumPeer@533] - currentEpoch
> not found! Creating with a reasonable default of 0. This should only happen
> when you are upgrading your installation
> 2016-07-12 22:34:58,057 [myid:] - INFO
> [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:11243:QuorumPeer@774] - LOOKING
> 2016-07-12 22:34:58,058 [myid:] - INFO
> [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:11243:FastLeaderElection@818] - New
> election. My id = 1, proposed zxid=0x0
> 2016-07-12 22:34:58,058 [myid:] - INFO
> [/0.0.0.0:11241:QuorumCnxManager$Listener@541] - Received connection request
> /140.211.11.27:46871
> 2016-07-12 22:34:58,063 [myid:] - INFO
> [WorkerReceiver[myid=1]:FastLeaderElection@600] - Notification: 1 (message
> format version), 1 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING
> (n.state), 1 (n.sid), 0x0 (n.peerEpoch) LOOKING (my state)
> 2016-07-12 22:34:58,064 [myid:] - INFO
> [WorkerReceiver[myid=0]:FastLeaderElection@600] - Notification: 1 (message
> format version), 1 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING
> (n.state), 1 (n.sid), 0x0 (n.peerEpoch) LOOKING (my state)
> 2016-07-12 22:34:58,064 [myid:] - INFO
> [WorkerReceiver[myid=1]:FastLeaderElection@600] - Notification: 1 (message
> format version), 0 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING
> (n.state), 0 (n.sid), 0x0 (n.peerEpoch) LOOKING (my state)
> 2016-07-12 22:34:58,065 [myid:] - INFO
> [WorkerReceiver[myid=0]:FastLeaderElection@600] - Notification: 1 (message
> format version), 1 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING
> (n.state), 0 (n.sid), 0x0 (n.peerEpoch) LOOKING (my state)
> 2016-07-12 22:34:58,065 [myid:] - INFO
> [WorkerReceiver[myid=1]:FastLeaderElection@600] - Notification: 1 (message
> format version), 1 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING
> (n.state), 0 (n.sid), 0x0 (n.peerEpoch) LOOKING (my state)
> 2016-07-12 22:34:58,065 [myid:] - WARN
> [WorkerSender[myid=1]:QuorumCnxManager@400] - Cannot open channel to 2 at
> election address /0.0.0.0:11247
> java.net.ConnectException: Connection refused
> at java.net.PlainSocketImpl.socketConnect(Native Method)
> at
> java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:345)
> at
> java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:204)
> at
> java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
> at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
> at java.net.Socket.connect(Socket.java:589)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.connectOne(QuorumCnxManager.java:381)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.toSend(QuorumCnxManager.java:354)
> at
> org.apache.zookeeper.server.quorum.FastLeaderElection$Messenger$WorkerSender.process(FastLeaderElection.java:452)
> at
> org.apache.zookeeper.server.quorum.FastLeaderElection$Messenger$WorkerSender.run(FastLeaderElection.java:433)
> at java.lang.Thread.run(Thread.java:744)
> 2016-07-12 22:34:58,065 [myid:] - WARN
> [WorkerSender[myid=0]:QuorumCnxManager@400] - Cannot open channel to 2 at
> election address /0.0.0.0:11247
> java.net.ConnectException: Connection refused
> at java.net.PlainSocketImpl.socketConnect(Native Method)
> at
> java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:345)
> at
> java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:204)
> at
> java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
> at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
> at java.net.Socket.connect(Socket.java:589)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.connectOne(QuorumCnxManager.java:381)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.toSend(QuorumCnxManager.java:354)
> at
> org.apache.zookeeper.server.quorum.FastLeaderElection$Messenger$WorkerSender.process(FastLeaderElection.java:452)
> at
> org.apache.zookeeper.server.quorum.FastLeaderElection$Messenger$WorkerSender.run(FastLeaderElection.java:433)
> at java.lang.Thread.run(Thread.java:744)
> 2016-07-12 22:34:58,066 [myid:] - INFO
> [WorkerSender[myid=1]:QuorumPeer$QuorumServer@149] - Resolved hostname:
> 0.0.0.0 to address: /0.0.0.0
> 2016-07-12 22:34:58,066 [myid:] - INFO
> [WorkerSender[myid=0]:QuorumPeer$QuorumServer@149] - Resolved hostname:
> 0.0.0.0 to address: /0.0.0.0
> 2016-07-12 22:34:58,084 [myid:] - INFO [main:QuorumPeer@548] - acceptedEpoch
> not found! Creating with a reasonable default of 0. This should only happen
> when you are upgrading your installation
> 2016-07-12 22:34:58,133 [myid:] - INFO
> [ListenerThread:QuorumCnxManager$Listener@534] - My election bind port:
> /0.0.0.0:11247
> 2016-07-12 22:34:58,136 [myid:] - INFO
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:11246:QuorumPeer@774] - LOOKING
> 2016-07-12 22:34:58,136 [myid:] - INFO
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:11246:FastLeaderElection@818] - New
> election. My id = 2, proposed zxid=0x0
> 2016-07-12 22:34:58,137 [myid:] - INFO
> [/0.0.0.0:11241:QuorumCnxManager$Listener@541] - Received connection request
> /140.211.11.27:46874
> 2016-07-12 22:34:58,138 [myid:] - INFO
> [/0.0.0.0:11244:QuorumCnxManager$Listener@541] - Received connection request
> /140.211.11.27:33135
> 2016-07-12 22:34:58,141 [myid:] - INFO
> [WorkerReceiver[myid=0]:FastLeaderElection@600] - Notification: 1 (message
> format version), 2 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING
> (n.state), 2 (n.sid), 0x0 (n.peerEpoch) LOOKING (my state)
> 2016-07-12 22:34:58,143 [myid:] - INFO
> [WorkerReceiver[myid=0]:FastLeaderElection@600] - Notification: 1 (message
> format version), 2 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING
> (n.state), 0 (n.sid), 0x0 (n.peerEpoch) LOOKING (my state)
> 2016-07-12 22:34:58,143 [myid:] - INFO
> [WorkerReceiver[myid=1]:FastLeaderElection@600] - Notification: 1 (message
> format version), 2 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING
> (n.state), 2 (n.sid), 0x0 (n.peerEpoch) LOOKING (my state)
> 2016-07-12 22:34:58,143 [myid:] - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@600] - Notification: 1 (message
> format version), 1 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING
> (n.state), 0 (n.sid), 0x0 (n.peerEpoch) LOOKING (my state)
> 2016-07-12 22:34:58,144 [myid:] - INFO
> [WorkerReceiver[myid=1]:FastLeaderElection@600] - Notification: 1 (message
> format version), 2 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING
> (n.state), 0 (n.sid), 0x0 (n.peerEpoch) LOOKING (my state)
> 2016-07-12 22:34:58,144 [myid:] - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@600] - Notification: 1 (message
> format version), 1 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING
> (n.state), 1 (n.sid), 0x0 (n.peerEpoch) LOOKING (my state)
> 2016-07-12 22:34:58,144 [myid:] - INFO
> [WorkerReceiver[myid=1]:FastLeaderElection@600] - Notification: 1 (message
> format version), 2 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING
> (n.state), 1 (n.sid), 0x0 (n.peerEpoch) LOOKING (my state)
> 2016-07-12 22:34:58,144 [myid:] - INFO
> [WorkerReceiver[myid=0]:FastLeaderElection@600] - Notification: 1 (message
> format version), 2 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING
> (n.state), 1 (n.sid), 0x0 (n.peerEpoch) LOOKING (my state)
> 2016-07-12 22:34:58,144 [myid:] - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@600] - Notification: 1 (message
> format version), 2 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING
> (n.state), 2 (n.sid), 0x0 (n.peerEpoch) LOOKING (my state)
> 2016-07-12 22:34:58,145 [myid:] - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@600] - Notification: 1 (message
> format version), 2 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING
> (n.state), 0 (n.sid), 0x0 (n.peerEpoch) LOOKING (my state)
> 2016-07-12 22:34:58,145 [myid:] - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@600] - Notification: 1 (message
> format version), 2 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING
> (n.state), 1 (n.sid), 0x0 (n.peerEpoch) LOOKING (my state)
> 2016-07-12 22:34:58,345 [myid:] - INFO
> [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:11243:QuorumPeer@844] - FOLLOWING
> 2016-07-12 22:34:58,345 [myid:] - INFO
> [QuorumPeer[myid=0]/0:0:0:0:0:0:0:0:11240:QuorumPeer@844] - FOLLOWING
> 2016-07-12 22:34:58,346 [myid:] - INFO
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:11246:QuorumPeer@856] - LEADING
> 2016-07-12 22:34:58,349 [myid:] - INFO
> [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:11243:Learner@86] - TCP NoDelay set to:
> true
> 2016-07-12 22:34:58,350 [myid:] - INFO
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:11246:Leader@59] - TCP NoDelay set to:
> true
> 2016-07-12 22:34:58,354 [myid:] - INFO
> [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:11243:Environment@100] - Server
> environment:zookeeper.version=3.4.9-SNAPSHOT-1752356, built on 07/12/2016
> 22:30 GMT
> 2016-07-12 22:34:58,354 [myid:] - INFO
> [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:11243:Environment@100] - Server
> environment:host.name=hemera.apache.org
> 2016-07-12 22:34:58,354 [myid:] - INFO
> [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:11243:Environment@100] - Server
> environment:java.version=1.8.0
> 2016-07-12 22:34:58,354 [myid:] - INFO
> [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:11243:Environment@100] - Server
> environment:java.vendor=Oracle Corporation
> 2016-07-12 22:34:58,354 [myid:] - INFO
> [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:11243:Environment@100] - Server
> environment:java.home=/x1/jenkins/jenkins-slave/tools/hudson.model.JDK/jdk-1.8.0/jre
> 2016-07-12 22:34:58,354 [myid:] - INFO
> [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:11243:Environment@100] - Server
> environment:java.class.path=/x1/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk8/branch-3.4/build/test/classes:/x1/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk8/branch-3.4/build/test/lib/antlr-2.7.6.jar:/x1/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk8/branch-3.4/build/test/lib/checkstyle-5.0.jar:/x1/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk8/branch-3.4/build/test/lib/commons-beanutils-core-1.7.0.jar:/x1/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk8/branch-3.4/build/test/lib/commons-cli-1.0.jar:/x1/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk8/branch-3.4/build/test/lib/commons-collections-3.2.2.jar:/x1/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk8/branch-3.4/build/test/lib/commons-lang-1.0.jar:/x1/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk8/branch-3.4/build/test/lib/commons-logging-1.0.3.jar:/x1/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk8/branch-3.4/build/test/lib/google-collections-0.9.jar:/x1/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk8/branch-3.4/build/test/lib/junit-4.8.1.jar:/x1/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk8/branch-3.4/build/test/lib/mockito-all-1.8.2.jar:/x1/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk8/branch-3.4/build/classes:/x1/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk8/branch-3.4/src/java/lib/ivy-2.4.0.jar:/home/jenkins/tools/ant/latest/lib/ant.jar:/x1/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk8/branch-3.4/build/lib/jline-0.9.94.jar:/x1/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk8/branch-3.4/build/lib/log4j-1.2.16.jar:/x1/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk8/branch-3.4/build/lib/netty-3.10.5.Final.jar:/x1/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk8/branch-3.4/build/lib/slf4j-api-1.6.1.jar:/x1/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk8/branch-3.4/build/lib/slf4j-log4j12-1.6.1.jar:/home/jenkins/tools/clover/latest/lib/clover.jar:/x1/jenkins/tools/ant/apache-ant-1.8.2/lib/ant-launcher.jar:/home/jenkins/tools/ant/latest/lib/ant-junit.jar:/home/jenkins/tools/ant/latest/lib/ant-junit4.jar
> 2016-07-12 22:34:58,355 [myid:] - INFO
> [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:11243:Environment@100] - Server
> environment:java.library.path=/usr/java/packages/lib/amd64:/usr/lib64:/lib64:/lib:/usr/lib
> 2016-07-12 22:34:58,355 [myid:] - INFO
> [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:11243:Environment@100] - Server
> environment:java.io.tmpdir=/tmp
> 2016-07-12 22:34:58,355 [myid:] - INFO
> [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:11243:Environment@100] - Server
> environment:java.compiler=<NA>
> 2016-07-12 22:34:58,355 [myid:] - INFO
> [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:11243:Environment@100] - Server
> environment:os.name=Linux
> 2016-07-12 22:34:58,355 [myid:] - INFO
> [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:11243:Environment@100] - Server
> environment:os.arch=amd64
> 2016-07-12 22:34:58,355 [myid:] - INFO
> [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:11243:Environment@100] - Server
> environment:os.version=3.2.0-104-generic
> 2016-07-12 22:34:58,355 [myid:] - INFO
> [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:11243:Environment@100] - Server
> environment:user.name=jenkins
> 2016-07-12 22:34:58,355 [myid:] - INFO
> [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:11243:Environment@100] - Server
> environment:user.home=/home/jenkins
> 2016-07-12 22:34:58,355 [myid:] - INFO
> [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:11243:Environment@100] - Server
> environment:user.dir=/x1/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk8/branch-3.4
> 2016-07-12 22:34:58,358 [myid:] - INFO
> [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:11243:ZooKeeperServer@170] - Created
> server with tickTime 1000 minSessionTimeout 2000 maxSessionTimeout 20000
> datadir
> /x1/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk8/branch-3.4/build/test/tmp/test6977370939981061612.junit.dir/version-2
> snapdir
> /x1/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk8/branch-3.4/build/test/tmp/test6977370939981061612.junit.dir/version-2
> 2016-07-12 22:34:58,358 [myid:] - INFO
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:11246:ZooKeeperServer@170] - Created
> server with tickTime 1000 minSessionTimeout 2000 maxSessionTimeout 20000
> datadir
> /x1/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk8/branch-3.4/build/test/tmp/test4996523116536588259.junit.dir/version-2
> snapdir
> /x1/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk8/branch-3.4/build/test/tmp/test4996523116536588259.junit.dir/version-2
> 2016-07-12 22:34:58,358 [myid:] - INFO
> [QuorumPeer[myid=0]/0:0:0:0:0:0:0:0:11240:ZooKeeperServer@170] - Created
> server with tickTime 1000 minSessionTimeout 2000 maxSessionTimeout 20000
> datadir
> /x1/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk8/branch-3.4/build/test/tmp/test8108741215991761367.junit.dir/version-2
> snapdir
> /x1/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk8/branch-3.4/build/test/tmp/test8108741215991761367.junit.dir/version-2
> 2016-07-12 22:34:58,359 [myid:] - INFO
> [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:11243:Follower@63] - FOLLOWING - LEADER
> ELECTION TOOK - 301
> 2016-07-12 22:34:58,359 [myid:] - INFO
> [QuorumPeer[myid=0]/0:0:0:0:0:0:0:0:11240:Follower@63] - FOLLOWING - LEADER
> ELECTION TOOK - 334
> 2016-07-12 22:34:58,365 [myid:] - INFO
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:11246:Leader@361] - LEADING - LEADER
> ELECTION TOOK - 224
> 2016-07-12 22:34:58,370 [myid:] - INFO
> [QuorumPeer[myid=0]/0:0:0:0:0:0:0:0:11240:QuorumPeer$QuorumServer@149] -
> Resolved hostname: 0.0.0.0 to address: /0.0.0.0
> 2016-07-12 22:34:58,373 [myid:] - INFO
> [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:11243:QuorumPeer$QuorumServer@149] -
> Resolved hostname: 0.0.0.0 to address: /0.0.0.0
> 2016-07-12 22:34:58,383 [myid:] - INFO
> [LearnerHandler-/140.211.11.27:45223:LearnerHandler@329] - Follower sid: 1 :
> info : org.apache.zookeeper.server.quorum.QuorumPeer$QuorumServer@4e46c644
> 2016-07-12 22:34:58,383 [myid:] - INFO
> [LearnerHandler-/140.211.11.27:45222:LearnerHandler@329] - Follower sid: 0 :
> info : org.apache.zookeeper.server.quorum.QuorumPeer$QuorumServer@23da3d
> 2016-07-12 22:34:58,528 [myid:] - INFO
> [LearnerHandler-/140.211.11.27:45222:LearnerHandler@384] - Synchronizing with
> Follower sid: 0 maxCommittedLog=0x0 minCommittedLog=0x0 peerLastZxid=0x0
> 2016-07-12 22:34:58,528 [myid:] - INFO
> [LearnerHandler-/140.211.11.27:45223:LearnerHandler@384] - Synchronizing with
> Follower sid: 1 maxCommittedLog=0x0 minCommittedLog=0x0 peerLastZxid=0x0
> 2016-07-12 22:34:58,529 [myid:] - INFO
> [LearnerHandler-/140.211.11.27:45222:LearnerHandler@393] - leader and
> follower are in sync, zxid=0x0
> 2016-07-12 22:34:58,529 [myid:] - INFO
> [LearnerHandler-/140.211.11.27:45223:LearnerHandler@393] - leader and
> follower are in sync, zxid=0x0
> 2016-07-12 22:34:58,529 [myid:] - INFO
> [LearnerHandler-/140.211.11.27:45223:LearnerHandler@458] - Sending DIFF
> 2016-07-12 22:34:58,529 [myid:] - INFO
> [LearnerHandler-/140.211.11.27:45222:LearnerHandler@458] - Sending DIFF
> 2016-07-12 22:34:58,530 [myid:] - INFO
> [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:11243:Learner@326] - Getting a diff from
> the leader 0x0
> 2016-07-12 22:34:58,530 [myid:] - INFO
> [QuorumPeer[myid=0]/0:0:0:0:0:0:0:0:11240:Learner@326] - Getting a diff from
> the leader 0x0
> 2016-07-12 22:34:58,534 [myid:] - INFO
> [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:11243:FileTxnSnapLog@240] - Snapshotting:
> 0x0 to
> /x1/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk8/branch-3.4/build/test/tmp/test6977370939981061612.junit.dir/version-2/snapshot.0
> 2016-07-12 22:34:58,534 [myid:] - INFO
> [QuorumPeer[myid=0]/0:0:0:0:0:0:0:0:11240:FileTxnSnapLog@240] - Snapshotting:
> 0x0 to
> /x1/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk8/branch-3.4/build/test/tmp/test8108741215991761367.junit.dir/version-2/snapshot.0
> 2016-07-12 22:34:58,623 [myid:] - INFO
> [LearnerHandler-/140.211.11.27:45222:LearnerHandler@518] - Received
> NEWLEADER-ACK message from 0
> 2016-07-12 22:34:58,623 [myid:] - INFO
> [LearnerHandler-/140.211.11.27:45223:LearnerHandler@518] - Received
> NEWLEADER-ACK message from 1
> 2016-07-12 22:34:58,623 [myid:] - INFO
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:11246:Leader@946] - Have quorum of
> supporters, sids: [ 0,2 ]; starting up and setting last processed zxid:
> 0x100000000
> 2016-07-12 22:34:58,634 [myid:] - INFO [main:CnxManagerTest@405] - Round 0,
> halting peer 0
> 2016-07-12 22:34:58,634 [myid:] - INFO [main:Follower@166] - shutdown called
> java.lang.Exception: shutdown Follower
> at
> org.apache.zookeeper.server.quorum.Follower.shutdown(Follower.java:166)
> at
> org.apache.zookeeper.server.quorum.QuorumPeer.shutdown(QuorumPeer.java:891)
> at
> org.apache.zookeeper.server.quorum.CnxManagerTest.testWorkerThreads(CnxManagerTest.java:407)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:483)
> at
> org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:44)
> at
> org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
> at
> org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:41)
> at
> org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:20)
> at
> org.apache.zookeeper.JUnit4ZKTestRunner$LoggedInvokeMethod.evaluate(JUnit4ZKTestRunner.java:55)
> at
> org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28)
> at org.junit.rules.TestWatchman$1.evaluate(TestWatchman.java:48)
> at
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:76)
> at
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50)
> at org.junit.runners.ParentRunner$3.run(ParentRunner.java:193)
> at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:52)
> at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:191)
> at org.junit.runners.ParentRunner.access$000(ParentRunner.java:42)
> at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:184)
> at org.junit.runners.ParentRunner.run(ParentRunner.java:236)
> at junit.framework.JUnit4TestAdapter.run(JUnit4TestAdapter.java:39)
> at
> org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.run(JUnitTestRunner.java:518)
> at
> org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.launch(JUnitTestRunner.java:1052)
> at
> org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.main(JUnitTestRunner.java:906)
> 2016-07-12 22:34:58,635 [myid:] - INFO [main:FollowerZooKeeperServer@140] -
> Shutting down
> 2016-07-12 22:34:58,645 [myid:] - INFO
> [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:11240:NIOServerCnxnFactory@219] -
> NIOServerCnxn factory exited run method
> 2016-07-12 22:34:58,645 [myid:] - INFO [main:FollowerZooKeeperServer@140] -
> Shutting down
> 2016-07-12 22:34:58,647 [myid:] - INFO [main:ZooKeeperServer@469] - shutting
> down
> 2016-07-12 22:34:58,647 [myid:] - INFO
> [QuorumPeer[myid=0]/0:0:0:0:0:0:0:0:11240:Follower@166] - shutdown called
> java.lang.Exception: shutdown Follower
> at
> org.apache.zookeeper.server.quorum.Follower.shutdown(Follower.java:166)
> at
> org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:850)
> 2016-07-12 22:34:58,648 [myid:] - INFO [main:FollowerRequestProcessor@107] -
> Shutting down
> 2016-07-12 22:34:58,648 [myid:] - INFO
> [QuorumPeer[myid=0]/0:0:0:0:0:0:0:0:11240:FollowerZooKeeperServer@140] -
> Shutting down
> 2016-07-12 22:34:58,648 [myid:] - INFO
> [FollowerRequestProcessor:0:FollowerRequestProcessor@97] -
> FollowerRequestProcessor exited loop!
> 2016-07-12 22:34:58,648 [myid:] - INFO [main:CommitProcessor@184] - Shutting
> down
> 2016-07-12 22:34:58,649 [myid:] - INFO [main:FinalRequestProcessor@402] -
> shutdown of request processor complete
> 2016-07-12 22:34:58,649 [myid:] - INFO
> [CommitProcessor:0:CommitProcessor@153] - CommitProcessor exited loop!
> 2016-07-12 22:34:58,650 [myid:] - INFO [main:SyncRequestProcessor@209] -
> Shutting down
> 2016-07-12 22:34:58,650 [myid:] - INFO
> [QuorumPeer[myid=0]/0:0:0:0:0:0:0:0:11240:SyncRequestProcessor@209] -
> Shutting down
> 2016-07-12 22:34:58,651 [myid:] - INFO
> [SyncThread:0:SyncRequestProcessor@187] - SyncRequestProcessor exited!
> 2016-07-12 22:34:58,651 [myid:] - WARN
> [QuorumPeer[myid=0]/0:0:0:0:0:0:0:0:11240:QuorumPeer@874] - QuorumPeer main
> thread exited
> 2016-07-12 22:34:58,651 [myid:] - ERROR
> [/0.0.0.0:11241:QuorumCnxManager$Listener@547] - Exception while listening
> java.net.SocketException: Socket closed
> at java.net.PlainSocketImpl.socketAccept(Native Method)
> at
> java.net.AbstractPlainSocketImpl.accept(AbstractPlainSocketImpl.java:404)
> at java.net.ServerSocket.implAccept(ServerSocket.java:545)
> at java.net.ServerSocket.accept(ServerSocket.java:513)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager$Listener.run(QuorumCnxManager.java:539)
> 2016-07-12 22:34:58,652 [myid:] - WARN
> [SendWorker:1:QuorumCnxManager$SendWorker@727] - Interrupted while waiting
> for message on queue
> java.lang.InterruptedException
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2014)
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2088)
> at
> java.util.concurrent.ArrayBlockingQueue.poll(ArrayBlockingQueue.java:418)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.pollSendQueue(QuorumCnxManager.java:879)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.access$500(QuorumCnxManager.java:65)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager$SendWorker.run(QuorumCnxManager.java:715)
> 2016-07-12 22:34:58,653 [myid:] - WARN
> [RecvWorker:2:QuorumCnxManager$RecvWorker@810] - Connection broken for id 2,
> my id = 0, error =
> java.net.SocketException: Socket closed
> at java.net.SocketInputStream.socketRead0(Native Method)
> at java.net.SocketInputStream.read(SocketInputStream.java:150)
> at java.net.SocketInputStream.read(SocketInputStream.java:121)
> at java.net.SocketInputStream.read(SocketInputStream.java:203)
> at java.io.DataInputStream.readInt(DataInputStream.java:387)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager$RecvWorker.run(QuorumCnxManager.java:795)
> 2016-07-12 22:34:58,654 [myid:] - WARN
> [RecvWorker:2:QuorumCnxManager$RecvWorker@813] - Interrupting SendWorker
> 2016-07-12 22:34:58,653 [myid:] - WARN
> [RecvWorker:0:QuorumCnxManager$RecvWorker@810] - Connection broken for id 0,
> my id = 2, error =
> java.io.EOFException
> at java.io.DataInputStream.readInt(DataInputStream.java:392)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager$RecvWorker.run(QuorumCnxManager.java:795)
> 2016-07-12 22:34:58,653 [myid:] - WARN
> [SendWorker:2:QuorumCnxManager$SendWorker@727] - Interrupted while waiting
> for message on queue
> java.lang.InterruptedException
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2014)
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2088)
> at
> java.util.concurrent.ArrayBlockingQueue.poll(ArrayBlockingQueue.java:418)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.pollSendQueue(QuorumCnxManager.java:879)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.access$500(QuorumCnxManager.java:65)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager$SendWorker.run(QuorumCnxManager.java:715)
> 2016-07-12 22:34:58,656 [myid:] - WARN
> [SendWorker:2:QuorumCnxManager$SendWorker@736] - Send worker leaving thread
> 2016-07-12 22:34:58,652 [myid:] - WARN
> [RecvWorker:0:QuorumCnxManager$RecvWorker@810] - Connection broken for id 0,
> 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:795)
> 2016-07-12 22:34:58,656 [myid:] - WARN
> [RecvWorker:0:QuorumCnxManager$RecvWorker@813] - Interrupting SendWorker
> 2016-07-12 22:34:58,652 [myid:] - WARN
> [RecvWorker:1:QuorumCnxManager$RecvWorker@810] - Connection broken for id 1,
> my id = 0, error =
> java.net.SocketException: Socket closed
> at java.net.SocketInputStream.socketRead0(Native Method)
> at java.net.SocketInputStream.read(SocketInputStream.java:150)
> at java.net.SocketInputStream.read(SocketInputStream.java:121)
> at java.net.SocketInputStream.read(SocketInputStream.java:203)
> at java.io.DataInputStream.readInt(DataInputStream.java:387)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager$RecvWorker.run(QuorumCnxManager.java:795)
> 2016-07-12 22:34:58,657 [myid:] - WARN
> [RecvWorker:1:QuorumCnxManager$RecvWorker@813] - Interrupting SendWorker
> 2016-07-12 22:34:58,657 [myid:] - WARN
> [SendWorker:0:QuorumCnxManager$SendWorker@727] - Interrupted while waiting
> for message on queue
> java.lang.InterruptedException
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2014)
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2088)
> at
> java.util.concurrent.ArrayBlockingQueue.poll(ArrayBlockingQueue.java:418)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.pollSendQueue(QuorumCnxManager.java:879)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.access$500(QuorumCnxManager.java:65)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager$SendWorker.run(QuorumCnxManager.java:715)
> 2016-07-12 22:34:58,658 [myid:] - WARN
> [SendWorker:0:QuorumCnxManager$SendWorker@736] - Send worker leaving thread
> 2016-07-12 22:34:58,655 [myid:] - WARN
> [RecvWorker:0:QuorumCnxManager$RecvWorker@813] - Interrupting SendWorker
> 2016-07-12 22:34:58,654 [myid:] - WARN
> [SendWorker:1:QuorumCnxManager$SendWorker@736] - Send worker leaving thread
> 2016-07-12 22:34:58,659 [myid:] - WARN
> [SendWorker:0:QuorumCnxManager$SendWorker@727] - Interrupted while waiting
> for message on queue
> java.lang.InterruptedException
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2014)
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2088)
> at
> java.util.concurrent.ArrayBlockingQueue.poll(ArrayBlockingQueue.java:418)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.pollSendQueue(QuorumCnxManager.java:879)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.access$500(QuorumCnxManager.java:65)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager$SendWorker.run(QuorumCnxManager.java:715)
> 2016-07-12 22:34:58,659 [myid:] - WARN
> [SendWorker:0:QuorumCnxManager$SendWorker@736] - Send worker leaving thread
> 2016-07-12 22:34:59,154 [myid:] - INFO [main:NIOServerCnxnFactory@89] -
> binding to port 0.0.0.0/0.0.0.0:11240
> 2016-07-12 22:34:59,155 [myid:] - INFO [main:CnxManagerTest@414] - Round {},
> restarting peer {}[Ljava.lang.Object;@12bc6874
> 2016-07-12 22:34:59,157 [myid:] - INFO [main:FileSnap@83] - Reading snapshot
> /x1/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk8/branch-3.4/build/test/tmp/test8108741215991761367.junit.dir/version-2/snapshot.0
> 2016-07-12 22:34:59,159 [myid:] - INFO
> [ListenerThread:QuorumCnxManager$Listener@534] - My election bind port:
> /0.0.0.0:11241
> 2016-07-12 22:34:59,161 [myid:] - INFO
> [QuorumPeer[myid=0]/0:0:0:0:0:0:0:0:11240:QuorumPeer@774] - LOOKING
> 2016-07-12 22:34:59,162 [myid:] - INFO
> [QuorumPeer[myid=0]/0:0:0:0:0:0:0:0:11240:FastLeaderElection@818] - New
> election. My id = 0, proposed zxid=0x0
> 2016-07-12 22:34:59,162 [myid:] - INFO
> [WorkerReceiver[myid=0]:FastLeaderElection@600] - Notification: 1 (message
> format version), 0 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING
> (n.state), 0 (n.sid), 0x1 (n.peerEpoch) LOOKING (my state)
> 2016-07-12 22:34:59,163 [myid:] - INFO
> [WorkerSender[myid=0]:QuorumCnxManager@199] - Have smaller server identifier,
> so dropping the connection: (1, 0)
> 2016-07-12 22:34:59,163 [myid:] - INFO
> [/0.0.0.0:11244:QuorumCnxManager$Listener@541] - Received connection request
> /140.211.11.27:33142
> 2016-07-12 22:34:59,163 [myid:] - INFO
> [/0.0.0.0:11247:QuorumCnxManager$Listener@541] - Received connection request
> /140.211.11.27:44785
> 2016-07-12 22:34:59,163 [myid:] - INFO
> [WorkerSender[myid=0]:QuorumCnxManager@199] - Have smaller server identifier,
> so dropping the connection: (2, 0)
> 2016-07-12 22:34:59,164 [myid:] - INFO
> [/0.0.0.0:11241:QuorumCnxManager$Listener@541] - Received connection request
> /140.211.11.27:46884
> 2016-07-12 22:34:59,166 [myid:] - INFO
> [/0.0.0.0:11241:QuorumCnxManager$Listener@541] - Received connection request
> /140.211.11.27:46885
> 2016-07-12 22:34:59,167 [myid:] - INFO
> [WorkerReceiver[myid=1]:FastLeaderElection@600] - Notification: 1 (message
> format version), 0 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING
> (n.state), 0 (n.sid), 0x1 (n.peerEpoch) FOLLOWING (my state)
> 2016-07-12 22:34:59,169 [myid:] - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@600] - Notification: 1 (message
> format version), 0 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING
> (n.state), 0 (n.sid), 0x1 (n.peerEpoch) LEADING (my state)
> 2016-07-12 22:34:59,169 [myid:] - INFO
> [WorkerReceiver[myid=0]:FastLeaderElection@600] - Notification: 1 (message
> format version), 2 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING
> (n.state), 1 (n.sid), 0x0 (n.peerEpoch) LOOKING (my state)
> 2016-07-12 22:34:59,169 [myid:] - INFO
> [WorkerReceiver[myid=0]:FastLeaderElection@600] - Notification: 1 (message
> format version), 2 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING
> (n.state), 2 (n.sid), 0x0 (n.peerEpoch) LOOKING (my state)
> 2016-07-12 22:34:59,169 [myid:] - INFO
> [WorkerReceiver[myid=0]:FastLeaderElection@600] - Notification: 1 (message
> format version), 2 (n.leader), 0x0 (n.zxid), 0x1 (n.round), FOLLOWING
> (n.state), 1 (n.sid), 0x1 (n.peerEpoch) LOOKING (my state)
> 2016-07-12 22:34:59,170 [myid:] - INFO
> [WorkerReceiver[myid=0]:FastLeaderElection@600] - Notification: 1 (message
> format version), 2 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LEADING
> (n.state), 2 (n.sid), 0x1 (n.peerEpoch) LOOKING (my state)
> 2016-07-12 22:34:59,170 [myid:] - INFO
> [QuorumPeer[myid=0]/0:0:0:0:0:0:0:0:11240:QuorumPeer@844] - FOLLOWING
> 2016-07-12 22:34:59,170 [myid:] - INFO
> [QuorumPeer[myid=0]/0:0:0:0:0:0:0:0:11240:ZooKeeperServer@170] - Created
> server with tickTime 1000 minSessionTimeout 2000 maxSessionTimeout 20000
> datadir
> /x1/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk8/branch-3.4/build/test/tmp/test8108741215991761367.junit.dir/version-2
> snapdir
> /x1/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk8/branch-3.4/build/test/tmp/test8108741215991761367.junit.dir/version-2
> 2016-07-12 22:34:59,170 [myid:] - INFO
> [QuorumPeer[myid=0]/0:0:0:0:0:0:0:0:11240:Follower@63] - FOLLOWING - LEADER
> ELECTION TOOK - 8
> 2016-07-12 22:34:59,171 [myid:] - INFO
> [QuorumPeer[myid=0]/0:0:0:0:0:0:0:0:11240:QuorumPeer$QuorumServer@149] -
> Resolved hostname: 0.0.0.0 to address: /0.0.0.0
> 2016-07-12 22:34:59,172 [myid:] - INFO
> [LearnerHandler-/140.211.11.27:45228:LearnerHandler@329] - Follower sid: 0 :
> info : org.apache.zookeeper.server.quorum.QuorumPeer$QuorumServer@23da3d
> 2016-07-12 22:34:59,172 [myid:] - INFO
> [LearnerHandler-/140.211.11.27:45228:LearnerHandler@384] - Synchronizing with
> Follower sid: 0 maxCommittedLog=0x0 minCommittedLog=0x0 peerLastZxid=0x0
> 2016-07-12 22:34:59,172 [myid:] - INFO
> [LearnerHandler-/140.211.11.27:45228:LearnerHandler@458] - Sending SNAP
> 2016-07-12 22:34:59,172 [myid:] - INFO
> [LearnerHandler-/140.211.11.27:45228:LearnerHandler@482] - Sending snapshot
> last zxid of peer is 0x0 zxid of leader is 0x100000000sent zxid of db as
> 0x100000000
> 2016-07-12 22:34:59,172 [myid:] - INFO
> [QuorumPeer[myid=0]/0:0:0:0:0:0:0:0:11240:Learner@329] - Getting a snapshot
> from leader
> 2016-07-12 22:34:59,174 [myid:] - INFO
> [QuorumPeer[myid=0]/0:0:0:0:0:0:0:0:11240:FileTxnSnapLog@240] - Snapshotting:
> 0x100000000 to
> /x1/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk8/branch-3.4/build/test/tmp/test8108741215991761367.junit.dir/version-2/snapshot.100000000
> 2016-07-12 22:34:59,284 [myid:] - INFO
> [LearnerHandler-/140.211.11.27:45228:LearnerHandler@518] - Received
> NEWLEADER-ACK message from 0
> 2016-07-12 22:34:59,652 [myid:] - INFO
> [/0.0.0.0:11241:QuorumCnxManager$Listener@560] - Leaving listener
> 2016-07-12 22:34:59,660 [myid:] - INFO [main:CnxManagerTest@405] - Round 1,
> halting peer 0
> 2016-07-12 22:34:59,660 [myid:] - INFO [main:Follower@166] - shutdown called
> j
> ...[truncated 254755 chars]...
> Keeper_branch34_jdk8/branch-3.4/build/test/tmp/test4996523116536588259.junit.dir/version-2
> snapdir
> /x1/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk8/branch-3.4/build/test/tmp/test4996523116536588259.junit.dir/version-2
> 2016-07-12 22:35:13,328 [myid:] - INFO
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:11246:Follower@63] - FOLLOWING - LEADER
> ELECTION TOOK - 3
> 2016-07-12 22:35:13,329 [myid:] - INFO
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:11246:QuorumPeer$QuorumServer@149] -
> Resolved hostname: 0.0.0.0 to address: /0.0.0.0
> 2016-07-12 22:35:13,329 [myid:] - INFO
> [LearnerHandler-/140.211.11.27:32997:LearnerHandler@329] - Follower sid: 2 :
> info : org.apache.zookeeper.server.quorum.QuorumPeer$QuorumServer@6f23fc6d
> 2016-07-12 22:35:13,330 [myid:] - INFO
> [LearnerHandler-/140.211.11.27:32997:LearnerHandler@384] - Synchronizing with
> Follower sid: 2 maxCommittedLog=0x0 minCommittedLog=0x0
> peerLastZxid=0x200000000
> 2016-07-12 22:35:13,330 [myid:] - INFO
> [LearnerHandler-/140.211.11.27:32997:LearnerHandler@393] - leader and
> follower are in sync, zxid=0x200000000
> 2016-07-12 22:35:13,330 [myid:] - INFO
> [LearnerHandler-/140.211.11.27:32997:LearnerHandler@458] - Sending DIFF
> 2016-07-12 22:35:13,330 [myid:] - INFO
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:11246:Learner@326] - Getting a diff from
> the leader 0x200000000
> 2016-07-12 22:35:13,331 [myid:] - INFO
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:11246:FileTxnSnapLog@240] - Snapshotting:
> 0x200000000 to
> /x1/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk8/branch-3.4/build/test/tmp/test4996523116536588259.junit.dir/version-2/snapshot.200000000
> 2016-07-12 22:35:13,376 [myid:] - INFO
> [LearnerHandler-/140.211.11.27:32997:LearnerHandler@518] - Received
> NEWLEADER-ACK message from 2
> 2016-07-12 22:35:13,821 [myid:] - INFO
> [/0.0.0.0:11247:QuorumCnxManager$Listener@560] - Leaving listener
> 2016-07-12 22:35:13,824 [myid:] - INFO [main:Follower@166] - shutdown called
> java.lang.Exception: shutdown Follower
> at
> org.apache.zookeeper.server.quorum.Follower.shutdown(Follower.java:166)
> at
> org.apache.zookeeper.server.quorum.QuorumPeer.shutdown(QuorumPeer.java:891)
> at
> org.apache.zookeeper.server.quorum.CnxManagerTest.testWorkerThreads(CnxManagerTest.java:424)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:483)
> at
> org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:44)
> at
> org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
> at
> org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:41)
> at
> org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:20)
> at
> org.apache.zookeeper.JUnit4ZKTestRunner$LoggedInvokeMethod.evaluate(JUnit4ZKTestRunner.java:55)
> at
> org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28)
> at org.junit.rules.TestWatchman$1.evaluate(TestWatchman.java:48)
> at
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:76)
> at
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50)
> at org.junit.runners.ParentRunner$3.run(ParentRunner.java:193)
> at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:52)
> at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:191)
> at org.junit.runners.ParentRunner.access$000(ParentRunner.java:42)
> at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:184)
> at org.junit.runners.ParentRunner.run(ParentRunner.java:236)
> at junit.framework.JUnit4TestAdapter.run(JUnit4TestAdapter.java:39)
> at
> org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.run(JUnitTestRunner.java:518)
> at
> org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.launch(JUnitTestRunner.java:1052)
> at
> org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.main(JUnitTestRunner.java:906)
> 2016-07-12 22:35:13,824 [myid:] - INFO [main:FollowerZooKeeperServer@140] -
> Shutting down
> 2016-07-12 22:35:13,824 [myid:] - INFO [main:ZooKeeperServer@469] - shutting
> down
> 2016-07-12 22:35:13,825 [myid:] - INFO [main:FollowerRequestProcessor@107] -
> Shutting down
> 2016-07-12 22:35:13,825 [myid:] - INFO [main:CommitProcessor@184] - Shutting
> down
> 2016-07-12 22:35:13,825 [myid:] - INFO [main:FinalRequestProcessor@402] -
> shutdown of request processor complete
> 2016-07-12 22:35:13,825 [myid:] - INFO
> [CommitProcessor:0:CommitProcessor@153] - CommitProcessor exited loop!
> 2016-07-12 22:35:13,826 [myid:] - INFO [main:SyncRequestProcessor@209] -
> Shutting down
> 2016-07-12 22:35:13,825 [myid:] - INFO
> [FollowerRequestProcessor:0:FollowerRequestProcessor@97] -
> FollowerRequestProcessor exited loop!
> 2016-07-12 22:35:13,826 [myid:] - INFO
> [SyncThread:0:SyncRequestProcessor@187] - SyncRequestProcessor exited!
> 2016-07-12 22:35:13,827 [myid:] - INFO
> [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:11240:NIOServerCnxnFactory@219] -
> NIOServerCnxn factory exited run method
> 2016-07-12 22:35:13,828 [myid:] - ERROR
> [/0.0.0.0:11241:QuorumCnxManager$Listener@547] - Exception while listening
> java.net.SocketException: Socket closed
> at java.net.PlainSocketImpl.socketAccept(Native Method)
> at
> java.net.AbstractPlainSocketImpl.accept(AbstractPlainSocketImpl.java:404)
> at java.net.ServerSocket.implAccept(ServerSocket.java:545)
> at java.net.ServerSocket.accept(ServerSocket.java:513)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager$Listener.run(QuorumCnxManager.java:539)
> 2016-07-12 22:35:13,829 [myid:] - INFO [main:Leader@496] - Shutting down
> 2016-07-12 22:35:13,828 [myid:] - WARN
> [RecvWorker:0:QuorumCnxManager$RecvWorker@810] - Connection broken for id 0,
> 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:795)
> 2016-07-12 22:35:13,829 [myid:] - WARN
> [RecvWorker:0:QuorumCnxManager$RecvWorker@813] - Interrupting SendWorker
> 2016-07-12 22:35:13,828 [myid:] - WARN
> [RecvWorker:0:QuorumCnxManager$RecvWorker@810] - Connection broken for id 0,
> my id = 2, error =
> java.io.EOFException
> at java.io.DataInputStream.readInt(DataInputStream.java:392)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager$RecvWorker.run(QuorumCnxManager.java:795)
> 2016-07-12 22:35:13,829 [myid:] - WARN
> [RecvWorker:0:QuorumCnxManager$RecvWorker@813] - Interrupting SendWorker
> 2016-07-12 22:35:13,828 [myid:] - WARN
> [SendWorker:2:QuorumCnxManager$SendWorker@727] - Interrupted while waiting
> for message on queue
> java.lang.InterruptedException
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2014)
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2088)
> at
> java.util.concurrent.ArrayBlockingQueue.poll(ArrayBlockingQueue.java:418)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.pollSendQueue(QuorumCnxManager.java:879)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.access$500(QuorumCnxManager.java:65)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager$SendWorker.run(QuorumCnxManager.java:715)
> 2016-07-12 22:35:13,830 [myid:] - WARN
> [SendWorker:2:QuorumCnxManager$SendWorker@736] - Send worker leaving thread
> 2016-07-12 22:35:13,828 [myid:] - WARN
> [SendWorker:1:QuorumCnxManager$SendWorker@727] - Interrupted while waiting
> for message on queue
> java.lang.InterruptedException
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2014)
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2088)
> at
> java.util.concurrent.ArrayBlockingQueue.poll(ArrayBlockingQueue.java:418)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.pollSendQueue(QuorumCnxManager.java:879)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.access$500(QuorumCnxManager.java:65)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager$SendWorker.run(QuorumCnxManager.java:715)
> 2016-07-12 22:35:13,830 [myid:] - WARN
> [SendWorker:1:QuorumCnxManager$SendWorker@736] - Send worker leaving thread
> 2016-07-12 22:35:13,828 [myid:] - WARN
> [RecvWorker:1:QuorumCnxManager$RecvWorker@810] - Connection broken for id 1,
> my id = 0, error =
> java.net.SocketException: Socket closed
> at java.net.SocketInputStream.socketRead0(Native Method)
> at java.net.SocketInputStream.read(SocketInputStream.java:150)
> at java.net.SocketInputStream.read(SocketInputStream.java:121)
> at java.net.SocketInputStream.read(SocketInputStream.java:203)
> at java.io.DataInputStream.readInt(DataInputStream.java:387)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager$RecvWorker.run(QuorumCnxManager.java:795)
> 2016-07-12 22:35:13,830 [myid:] - WARN
> [RecvWorker:1:QuorumCnxManager$RecvWorker@813] - Interrupting SendWorker
> 2016-07-12 22:35:13,830 [myid:] - WARN
> [SendWorker:0:QuorumCnxManager$SendWorker@727] - Interrupted while waiting
> for message on queue
> java.lang.InterruptedException
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2014)
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2088)
> at
> java.util.concurrent.ArrayBlockingQueue.poll(ArrayBlockingQueue.java:418)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.pollSendQueue(QuorumCnxManager.java:879)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.access$500(QuorumCnxManager.java:65)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager$SendWorker.run(QuorumCnxManager.java:715)
> 2016-07-12 22:35:13,830 [myid:] - WARN
> [SendWorker:0:QuorumCnxManager$SendWorker@736] - Send worker leaving thread
> 2016-07-12 22:35:13,829 [myid:] - WARN
> [SendWorker:0:QuorumCnxManager$SendWorker@727] - Interrupted while waiting
> for message on queue
> java.lang.InterruptedException
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2014)
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2088)
> at
> java.util.concurrent.ArrayBlockingQueue.poll(ArrayBlockingQueue.java:418)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.pollSendQueue(QuorumCnxManager.java:879)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.access$500(QuorumCnxManager.java:65)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager$SendWorker.run(QuorumCnxManager.java:715)
> 2016-07-12 22:35:13,831 [myid:] - WARN
> [SendWorker:0:QuorumCnxManager$SendWorker@736] - Send worker leaving thread
> 2016-07-12 22:35:13,829 [myid:] - WARN
> [RecvWorker:2:QuorumCnxManager$RecvWorker@810] - Connection broken for id 2,
> my id = 0, error =
> java.net.SocketException: Socket closed
> at java.net.SocketInputStream.socketRead0(Native Method)
> at java.net.SocketInputStream.read(SocketInputStream.java:150)
> at java.net.SocketInputStream.read(SocketInputStream.java:121)
> at java.net.SocketInputStream.read(SocketInputStream.java:203)
> at java.io.DataInputStream.readInt(DataInputStream.java:387)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager$RecvWorker.run(QuorumCnxManager.java:795)
> 2016-07-12 22:35:13,831 [myid:] - WARN
> [RecvWorker:2:QuorumCnxManager$RecvWorker@813] - Interrupting SendWorker
> 2016-07-12 22:35:13,829 [myid:] - INFO [main:Leader@502] - Shutdown called
> java.lang.Exception: shutdown Leader! reason: quorum Peer shutdown
> at org.apache.zookeeper.server.quorum.Leader.shutdown(Leader.java:502)
> at
> org.apache.zookeeper.server.quorum.QuorumPeer.shutdown(QuorumPeer.java:888)
> at
> org.apache.zookeeper.server.quorum.CnxManagerTest.testWorkerThreads(CnxManagerTest.java:424)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:483)
> at
> org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:44)
> at
> org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
> at
> org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:41)
> at
> org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:20)
> at
> org.apache.zookeeper.JUnit4ZKTestRunner$LoggedInvokeMethod.evaluate(JUnit4ZKTestRunner.java:55)
> at
> org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28)
> at org.junit.rules.TestWatchman$1.evaluate(TestWatchman.java:48)
> at
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:76)
> at
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50)
> at org.junit.runners.ParentRunner$3.run(ParentRunner.java:193)
> at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:52)
> at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:191)
> at org.junit.runners.ParentRunner.access$000(ParentRunner.java:42)
> at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:184)
> at org.junit.runners.ParentRunner.run(ParentRunner.java:236)
> at junit.framework.JUnit4TestAdapter.run(JUnit4TestAdapter.java:39)
> at
> org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.run(JUnitTestRunner.java:518)
> at
> org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.launch(JUnitTestRunner.java:1052)
> at
> org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.main(JUnitTestRunner.java:906)
> 2016-07-12 22:35:13,831 [myid:] - INFO [main:ZooKeeperServer@469] - shutting
> down
> 2016-07-12 22:35:13,831 [myid:] - INFO [main:SessionTrackerImpl@225] -
> Shutting down
> 2016-07-12 22:35:13,832 [myid:] - INFO [main:PrepRequestProcessor@765] -
> Shutting down
> 2016-07-12 22:35:13,832 [myid:] - INFO [main:ProposalRequestProcessor@88] -
> Shutting down
> 2016-07-12 22:35:13,832 [myid:] - INFO [main:CommitProcessor@184] - Shutting
> down
> 2016-07-12 22:35:13,832 [myid:] - INFO
> [main:Leader$ToBeAppliedRequestProcessor@661] - Shutting down
> 2016-07-12 22:35:13,832 [myid:] - INFO [main:FinalRequestProcessor@402] -
> shutdown of request processor complete
> 2016-07-12 22:35:13,832 [myid:] - INFO [main:SyncRequestProcessor@209] -
> Shutting down
> 2016-07-12 22:35:13,831 [myid:] - INFO
> [LearnerCnxAcceptor-/0.0.0.0:11242:Leader$LearnerCnxAcceptor@325] - exception
> while shutting down acceptor: java.net.SocketException: Socket closed
> 2016-07-12 22:35:13,832 [myid:] - INFO
> [SyncThread:1:SyncRequestProcessor@187] - SyncRequestProcessor exited!
> 2016-07-12 22:35:13,832 [myid:] - INFO
> [CommitProcessor:1:CommitProcessor@153] - CommitProcessor exited loop!
> 2016-07-12 22:35:13,832 [myid:] - INFO [ProcessThread(sid:1
> cport:-1)::PrepRequestProcessor@143] - PrepRequestProcessor exited loop!
> 2016-07-12 22:35:13,834 [myid:] - WARN
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:11246:Follower@89] - Exception when
> following the leader
> java.io.EOFException
> at java.io.DataInputStream.readInt(DataInputStream.java:392)
> at
> org.apache.jute.BinaryInputArchive.readInt(BinaryInputArchive.java:63)
> at
> org.apache.zookeeper.server.quorum.QuorumPacket.deserialize(QuorumPacket.java:83)
> at
> org.apache.jute.BinaryInputArchive.readRecord(BinaryInputArchive.java:99)
> at
> org.apache.zookeeper.server.quorum.Learner.readPacket(Learner.java:153)
> at
> org.apache.zookeeper.server.quorum.Follower.followLeader(Follower.java:85)
> at
> org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:846)
> 2016-07-12 22:35:13,833 [myid:] - WARN
> [LearnerHandler-/140.211.11.27:32993:LearnerHandler@644] - ******* GOODBYE
> /140.211.11.27:32993 ********
> 2016-07-12 22:35:13,835 [myid:] - WARN
> [LearnerHandler-/140.211.11.27:32990:LearnerHandler@644] - ******* GOODBYE
> /140.211.11.27:32990 ********
> 2016-07-12 22:35:13,834 [myid:] - WARN
> [LearnerHandler-/140.211.11.27:32980:LearnerHandler@644] - ******* GOODBYE
> /140.211.11.27:32980 ********
> 2016-07-12 22:35:13,835 [myid:] - WARN
> [LearnerHandler-/140.211.11.27:32980:LearnerHandler@656] - Ignoring
> unexpected exception
> java.lang.InterruptedException
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireInterruptibly(AbstractQueuedSynchronizer.java:1220)
> at
> java.util.concurrent.locks.ReentrantLock.lockInterruptibly(ReentrantLock.java:335)
> at
> java.util.concurrent.LinkedBlockingQueue.put(LinkedBlockingQueue.java:339)
> at
> org.apache.zookeeper.server.quorum.LearnerHandler.shutdown(LearnerHandler.java:654)
> at
> org.apache.zookeeper.server.quorum.LearnerHandler.run(LearnerHandler.java:647)
> 2016-07-12 22:35:13,834 [myid:] - WARN
> [LearnerHandler-/140.211.11.27:32997:LearnerHandler@644] - ******* GOODBYE
> /140.211.11.27:32997 ********
> 2016-07-12 22:35:13,835 [myid:] - WARN
> [LearnerHandler-/140.211.11.27:32997:LearnerHandler@656] - Ignoring
> unexpected exception
> java.lang.InterruptedException
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireInterruptibly(AbstractQueuedSynchronizer.java:1220)
> at
> java.util.concurrent.locks.ReentrantLock.lockInterruptibly(ReentrantLock.java:335)
> at
> java.util.concurrent.LinkedBlockingQueue.put(LinkedBlockingQueue.java:339)
> at
> org.apache.zookeeper.server.quorum.LearnerHandler.shutdown(LearnerHandler.java:654)
> at
> org.apache.zookeeper.server.quorum.LearnerHandler.run(LearnerHandler.java:647)
> 2016-07-12 22:35:13,835 [myid:] - INFO
> [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:11243:NIOServerCnxnFactory@219] -
> NIOServerCnxn factory exited run method
> 2016-07-12 22:35:13,835 [myid:] - WARN
> [LearnerHandler-/140.211.11.27:32990:LearnerHandler@656] - Ignoring
> unexpected exception
> java.lang.InterruptedException
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireInterruptibly(AbstractQueuedSynchronizer.java:1220)
> at
> java.util.concurrent.locks.ReentrantLock.lockInterruptibly(ReentrantLock.java:335)
> at
> java.util.concurrent.LinkedBlockingQueue.put(LinkedBlockingQueue.java:339)
> at
> org.apache.zookeeper.server.quorum.LearnerHandler.shutdown(LearnerHandler.java:654)
> at
> org.apache.zookeeper.server.quorum.LearnerHandler.run(LearnerHandler.java:647)
> 2016-07-12 22:35:13,836 [myid:] - WARN
> [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:11243:QuorumPeer@862] - Unexpected
> exception
> java.lang.InterruptedException: sleep interrupted
> at java.lang.Thread.sleep(Native Method)
> at org.apache.zookeeper.server.quorum.Leader.lead(Leader.java:456)
> at
> org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:859)
> 2016-07-12 22:35:13,836 [myid:] - INFO
> [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:11243:Leader@496] - Shutting down
> 2016-07-12 22:35:13,836 [myid:] - WARN
> [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:11243:QuorumPeer@874] - QuorumPeer main
> thread exited
> 2016-07-12 22:35:13,835 [myid:] - INFO
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:11246:Follower@166] - shutdown called
> java.lang.Exception: shutdown Follower
> at
> org.apache.zookeeper.server.quorum.Follower.shutdown(Follower.java:166)
> at
> org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:850)
> 2016-07-12 22:35:13,837 [myid:] - INFO
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:11246:FollowerZooKeeperServer@140] -
> Shutting down
> 2016-07-12 22:35:13,837 [myid:] - INFO
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:11246:ZooKeeperServer@469] - shutting down
> 2016-07-12 22:35:13,837 [myid:] - INFO
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:11246:FollowerRequestProcessor@107] -
> Shutting down
> 2016-07-12 22:35:13,835 [myid:] - WARN
> [LearnerHandler-/140.211.11.27:32993:LearnerHandler@656] - Ignoring
> unexpected exception
> java.lang.InterruptedException
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireInterruptibly(AbstractQueuedSynchronizer.java:1220)
> at
> java.util.concurrent.locks.ReentrantLock.lockInterruptibly(ReentrantLock.java:335)
> at
> java.util.concurrent.LinkedBlockingQueue.put(LinkedBlockingQueue.java:339)
> at
> org.apache.zookeeper.server.quorum.LearnerHandler.shutdown(LearnerHandler.java:654)
> at
> org.apache.zookeeper.server.quorum.LearnerHandler.run(LearnerHandler.java:647)
> 2016-07-12 22:35:13,835 [myid:] - WARN
> [QuorumPeer[myid=0]/0:0:0:0:0:0:0:0:11240:Follower@89] - Exception when
> following the leader
> java.io.EOFException
> at java.io.DataInputStream.readInt(DataInputStream.java:392)
> at
> org.apache.jute.BinaryInputArchive.readInt(BinaryInputArchive.java:63)
> at
> org.apache.zookeeper.server.quorum.QuorumPacket.deserialize(QuorumPacket.java:83)
> at
> org.apache.jute.BinaryInputArchive.readRecord(BinaryInputArchive.java:99)
> at
> org.apache.zookeeper.server.quorum.Learner.readPacket(Learner.java:153)
> at
> org.apache.zookeeper.server.quorum.Follower.followLeader(Follower.java:85)
> at
> org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:846)
> 2016-07-12 22:35:13,837 [myid:] - INFO
> [FollowerRequestProcessor:2:FollowerRequestProcessor@97] -
> FollowerRequestProcessor exited loop!
> 2016-07-12 22:35:13,838 [myid:] - INFO
> [QuorumPeer[myid=0]/0:0:0:0:0:0:0:0:11240:Follower@166] - shutdown called
> java.lang.Exception: shutdown Follower
> at
> org.apache.zookeeper.server.quorum.Follower.shutdown(Follower.java:166)
> at
> org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:850)
> 2016-07-12 22:35:13,837 [myid:] - INFO
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:11246:CommitProcessor@184] - Shutting down
> 2016-07-12 22:35:13,839 [myid:] - INFO
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:11246:FinalRequestProcessor@402] -
> shutdown of request processor complete
> 2016-07-12 22:35:13,839 [myid:] - INFO
> [CommitProcessor:2:CommitProcessor@153] - CommitProcessor exited loop!
> 2016-07-12 22:35:13,837 [myid:] - INFO [main:Follower@166] - shutdown called
> java.lang.Exception: shutdown Follower
> at
> org.apache.zookeeper.server.quorum.Follower.shutdown(Follower.java:166)
> at
> org.apache.zookeeper.server.quorum.QuorumPeer.shutdown(QuorumPeer.java:891)
> at
> org.apache.zookeeper.server.quorum.CnxManagerTest.testWorkerThreads(CnxManagerTest.java:424)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:483)
> at
> org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:44)
> at
> org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
> at
> org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:41)
> at
> org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:20)
> at
> org.apache.zookeeper.JUnit4ZKTestRunner$LoggedInvokeMethod.evaluate(JUnit4ZKTestRunner.java:55)
> at
> org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28)
> at org.junit.rules.TestWatchman$1.evaluate(TestWatchman.java:48)
> at
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:76)
> at
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50)
> at org.junit.runners.ParentRunner$3.run(ParentRunner.java:193)
> at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:52)
> at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:191)
> at org.junit.runners.ParentRunner.access$000(ParentRunner.java:42)
> at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:184)
> at org.junit.runners.ParentRunner.run(ParentRunner.java:236)
> at junit.framework.JUnit4TestAdapter.run(JUnit4TestAdapter.java:39)
> at
> org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.run(JUnitTestRunner.java:518)
> at
> org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.launch(JUnitTestRunner.java:1052)
> at
> org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.main(JUnitTestRunner.java:906)
> 2016-07-12 22:35:13,839 [myid:] - INFO [main:FollowerZooKeeperServer@140] -
> Shutting down
> 2016-07-12 22:35:13,839 [myid:] - INFO [main:SyncRequestProcessor@209] -
> Shutting down
> 2016-07-12 22:35:13,836 [myid:] - WARN
> [RecvWorker:2:QuorumCnxManager$RecvWorker@810] - Connection broken for id 2,
> my id = 1, error =
> java.net.SocketException: Socket closed
> at java.net.SocketInputStream.socketRead0(Native Method)
> at java.net.SocketInputStream.read(SocketInputStream.java:150)
> at java.net.SocketInputStream.read(SocketInputStream.java:121)
> at java.net.SocketInputStream.read(SocketInputStream.java:203)
> at java.io.DataInputStream.readInt(DataInputStream.java:387)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager$RecvWorker.run(QuorumCnxManager.java:795)
> 2016-07-12 22:35:13,840 [myid:] - WARN
> [RecvWorker:2:QuorumCnxManager$RecvWorker@813] - Interrupting SendWorker
> 2016-07-12 22:35:13,836 [myid:] - WARN
> [RecvWorker:1:QuorumCnxManager$RecvWorker@810] - Connection broken for id 1,
> my id = 2, error =
> java.io.EOFException
> at java.io.DataInputStream.readInt(DataInputStream.java:392)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager$RecvWorker.run(QuorumCnxManager.java:795)
> 2016-07-12 22:35:13,840 [myid:] - WARN
> [RecvWorker:1:QuorumCnxManager$RecvWorker@813] - Interrupting SendWorker
> 2016-07-12 22:35:13,836 [myid:] - WARN
> [SendWorker:2:QuorumCnxManager$SendWorker@727] - Interrupted while waiting
> for message on queue
> java.lang.InterruptedException
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2014)
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2088)
> at
> java.util.concurrent.ArrayBlockingQueue.poll(ArrayBlockingQueue.java:418)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.pollSendQueue(QuorumCnxManager.java:879)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.access$500(QuorumCnxManager.java:65)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager$SendWorker.run(QuorumCnxManager.java:715)
> 2016-07-12 22:35:13,840 [myid:] - WARN
> [SendWorker:2:QuorumCnxManager$SendWorker@736] - Send worker leaving thread
> 2016-07-12 22:35:13,836 [myid:] - ERROR
> [/0.0.0.0:11244:QuorumCnxManager$Listener@547] - Exception while listening
> java.net.SocketException: Socket closed
> at java.net.PlainSocketImpl.socketAccept(Native Method)
> at
> java.net.AbstractPlainSocketImpl.accept(AbstractPlainSocketImpl.java:404)
> at java.net.ServerSocket.implAccept(ServerSocket.java:545)
> at java.net.ServerSocket.accept(ServerSocket.java:513)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager$Listener.run(QuorumCnxManager.java:539)
> 2016-07-12 22:35:13,840 [myid:] - WARN
> [SendWorker:1:QuorumCnxManager$SendWorker@727] - Interrupted while waiting
> for message on queue
> java.lang.InterruptedException
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2014)
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2088)
> at
> java.util.concurrent.ArrayBlockingQueue.poll(ArrayBlockingQueue.java:418)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.pollSendQueue(QuorumCnxManager.java:879)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.access$500(QuorumCnxManager.java:65)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager$SendWorker.run(QuorumCnxManager.java:715)
> 2016-07-12 22:35:13,841 [myid:] - WARN
> [SendWorker:1:QuorumCnxManager$SendWorker@736] - Send worker leaving thread
> 2016-07-12 22:35:13,840 [myid:] - INFO
> [SyncThread:2:SyncRequestProcessor@187] - SyncRequestProcessor exited!
> 2016-07-12 22:35:13,839 [myid:] - INFO
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:11246:SyncRequestProcessor@209] -
> Shutting down
> 2016-07-12 22:35:13,841 [myid:] - WARN
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:11246:QuorumPeer@874] - QuorumPeer main
> thread exited
> 2016-07-12 22:35:13,841 [myid:] - INFO
> [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:11246:NIOServerCnxnFactory@219] -
> NIOServerCnxn factory exited run method
> 2016-07-12 22:35:13,839 [myid:] - INFO
> [QuorumPeer[myid=0]/0:0:0:0:0:0:0:0:11240:FollowerZooKeeperServer@140] -
> Shutting down
> 2016-07-12 22:35:13,842 [myid:] - INFO
> [QuorumPeer[myid=0]/0:0:0:0:0:0:0:0:11240:SyncRequestProcessor@209] -
> Shutting down
> 2016-07-12 22:35:13,842 [myid:] - WARN
> [QuorumPeer[myid=0]/0:0:0:0:0:0:0:0:11240:QuorumPeer@874] - QuorumPeer main
> thread exited
> 2016-07-12 22:35:13,842 [myid:] - INFO
> [main:JUnit4ZKTestRunner$LoggedInvokeMethod@58] - Memory used 11673
> 2016-07-12 22:35:13,842 [myid:] - ERROR
> [/0.0.0.0:11247:QuorumCnxManager$Listener@547] - Exception while listening
> java.net.SocketException: Socket closed
> at java.net.PlainSocketImpl.socketAccept(Native Method)
> at
> java.net.AbstractPlainSocketImpl.accept(AbstractPlainSocketImpl.java:404)
> at java.net.ServerSocket.implAccept(ServerSocket.java:545)
> at java.net.ServerSocket.accept(ServerSocket.java:513)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager$Listener.run(QuorumCnxManager.java:539)
> 2016-07-12 22:35:13,842 [myid:] - INFO
> [main:JUnit4ZKTestRunner$LoggedInvokeMethod@63] - Number of threads 20
> 2016-07-12 22:35:13,842 [myid:] - INFO
> [main:JUnit4ZKTestRunner$LoggedInvokeMethod@78] - FINISHED TEST METHOD
> testWorkerThreads
> 2016-07-12 22:35:13,842 [myid:] - INFO [main:ZKTestCase$1@60] - SUCCEEDED
> testWorkerThreads
> 2016-07-12 22:35:13,843 [myid:] - INFO [main:ZKTestCase$1@55] - FINISHED
> testWorkerThreads
> 2016-07-12 22:35:13,843 [myid:] - INFO [main:ZKTestCase$1@50] - STARTING
> testCnxManager
> 2016-07-12 22:35:13,843 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11248
> 2016-07-12 22:35:13,843 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11249
> 2016-07-12 22:35:13,843 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11250
> 2016-07-12 22:35:13,843 [myid:] - INFO [main:QuorumPeer$QuorumServer@149] -
> Resolved hostname: 0.0.0.0 to address: /0.0.0.0
> 2016-07-12 22:35:13,844 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11251
> 2016-07-12 22:35:13,844 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11252
> 2016-07-12 22:35:13,844 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11253
> 2016-07-12 22:35:13,844 [myid:] - INFO [main:QuorumPeer$QuorumServer@149] -
> Resolved hostname: 0.0.0.0 to address: /0.0.0.0
> 2016-07-12 22:35:13,844 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11254
> 2016-07-12 22:35:13,844 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11255
> 2016-07-12 22:35:13,844 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11256
> 2016-07-12 22:35:13,844 [myid:] - INFO [main:QuorumPeer$QuorumServer@149] -
> Resolved hostname: 0.0.0.0 to address: /0.0.0.0
> 2016-07-12 22:35:13,844 [myid:] - INFO
> [main:JUnit4ZKTestRunner$LoggedInvokeMethod@53] - RUNNING TEST METHOD
> testCnxManager
> 2016-07-12 22:35:13,845 [myid:] - INFO [main:NIOServerCnxnFactory@89] -
> binding to port 0.0.0.0/0.0.0.0:11252
> 2016-07-12 22:35:13,846 [myid:] - INFO [Thread-19:NIOServerCnxnFactory@89] -
> binding to port 0.0.0.0/0.0.0.0:11249
> 2016-07-12 22:35:13,846 [myid:] - INFO
> [ListenerThread:QuorumCnxManager$Listener@534] - My election bind port:
> /0.0.0.0:11253
> 2016-07-12 22:35:13,846 [myid:] - WARN [main:QuorumCnxManager@400] - Cannot
> open channel to 0 at election address /0.0.0.0:11250
> java.net.ConnectException: Connection refused
> at java.net.PlainSocketImpl.socketConnect(Native Method)
> at
> java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:345)
> at
> java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:204)
> at
> java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
> at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
> at java.net.Socket.connect(Socket.java:589)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.connectOne(QuorumCnxManager.java:381)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.toSend(QuorumCnxManager.java:354)
> at
> org.apache.zookeeper.server.quorum.CnxManagerTest.testCnxManager(CnxManagerTest.java:142)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:483)
> at
> org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:44)
> at
> org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
> at
> org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:41)
> at
> org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:20)
> at
> org.apache.zookeeper.JUnit4ZKTestRunner$LoggedInvokeMethod.evaluate(JUnit4ZKTestRunner.java:55)
> at
> org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28)
> at org.junit.rules.TestWatchman$1.evaluate(TestWatchman.java:48)
> at
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:76)
> at
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50)
> at org.junit.runners.ParentRunner$3.run(ParentRunner.java:193)
> at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:52)
> at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:191)
> at org.junit.runners.ParentRunner.access$000(ParentRunner.java:42)
> at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:184)
> at org.junit.runners.ParentRunner.run(ParentRunner.java:236)
> at junit.framework.JUnit4TestAdapter.run(JUnit4TestAdapter.java:39)
> at
> org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.run(JUnitTestRunner.java:518)
> at
> org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.launch(JUnitTestRunner.java:1052)
> at
> org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.main(JUnitTestRunner.java:906)
> 2016-07-12 22:35:13,847 [myid:] - INFO [main:QuorumPeer$QuorumServer@149] -
> Resolved hostname: 0.0.0.0 to address: /0.0.0.0
> 2016-07-12 22:35:13,847 [myid:] - INFO
> [ListenerThread:QuorumCnxManager$Listener@534] - My election bind port:
> /0.0.0.0:11250
> 2016-07-12 22:35:13,847 [myid:] - INFO
> [/0.0.0.0:11253:QuorumCnxManager$Listener@541] - Received connection request
> /140.211.11.27:41746
> 2016-07-12 22:35:13,847 [myid:] - INFO [Thread-19:QuorumCnxManager@199] -
> Have smaller server identifier, so dropping the connection: (1, 0)
> 2016-07-12 22:35:13,848 [myid:] - INFO
> [/0.0.0.0:11250:QuorumCnxManager$Listener@541] - Received connection request
> /140.211.11.27:46883
> 2016-07-12 22:35:13,849 [myid:] - INFO
> [/0.0.0.0:11253:QuorumCnxManager$Listener@541] - Received connection request
> /140.211.11.27:41748
> 2016-07-12 22:35:13,849 [myid:] - INFO [Thread-19:QuorumCnxManager@199] -
> Have smaller server identifier, so dropping the connection: (1, 0)
> 2016-07-12 22:35:13,849 [myid:] - WARN
> [SendWorker:0:QuorumCnxManager$SendWorker@727] - Interrupted while waiting
> for message on queue
> java.lang.InterruptedException
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2014)
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2088)
> at
> java.util.concurrent.ArrayBlockingQueue.poll(ArrayBlockingQueue.java:418)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.pollSendQueue(QuorumCnxManager.java:879)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.access$500(QuorumCnxManager.java:65)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager$SendWorker.run(QuorumCnxManager.java:715)
> 2016-07-12 22:35:13,849 [myid:] - INFO
> [/0.0.0.0:11250:QuorumCnxManager$Listener@541] - Received connection request
> /140.211.11.27:46885
> 2016-07-12 22:35:13,849 [myid:] - WARN
> [SendWorker:0:QuorumCnxManager$SendWorker@736] - Send worker leaving thread
> 2016-07-12 22:35:13,849 [myid:] - WARN
> [RecvWorker:0:QuorumCnxManager$RecvWorker@810] - 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:150)
> at java.net.SocketInputStream.read(SocketInputStream.java:121)
> at java.net.SocketInputStream.read(SocketInputStream.java:203)
> at java.io.DataInputStream.readInt(DataInputStream.java:387)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager$RecvWorker.run(QuorumCnxManager.java:795)
> 2016-07-12 22:35:13,850 [myid:] - WARN
> [RecvWorker:0:QuorumCnxManager$RecvWorker@813] - Interrupting SendWorker
> 2016-07-12 22:35:13,849 [myid:] - WARN
> [RecvWorker:1:QuorumCnxManager$RecvWorker@810] - 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:795)
> 2016-07-12 22:35:13,850 [myid:] - WARN
> [RecvWorker:1:QuorumCnxManager$RecvWorker@813] - Interrupting SendWorker
> 2016-07-12 22:35:13,850 [myid:] - WARN
> [SendWorker:1:QuorumCnxManager$SendWorker@727] - Interrupted while waiting
> for message on queue
> java.lang.InterruptedException
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2014)
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2088)
> at
> java.util.concurrent.ArrayBlockingQueue.poll(ArrayBlockingQueue.java:418)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.pollSendQueue(QuorumCnxManager.java:879)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.access$500(QuorumCnxManager.java:65)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager$SendWorker.run(QuorumCnxManager.java:715)
> 2016-07-12 22:35:13,851 [myid:] - WARN
> [SendWorker:1:QuorumCnxManager$SendWorker@736] - Send worker leaving thread
> 2016-07-12 22:35:13,851 [myid:] - INFO
> [main:JUnit4ZKTestRunner$LoggedInvokeMethod@58] - Memory used 12332
> 2016-07-12 22:35:13,851 [myid:] - INFO
> [main:JUnit4ZKTestRunner$LoggedInvokeMethod@63] - Number of threads 26
> 2016-07-12 22:35:13,851 [myid:] - INFO
> [main:JUnit4ZKTestRunner$LoggedInvokeMethod@78] - FINISHED TEST METHOD
> testCnxManager
> 2016-07-12 22:35:13,851 [myid:] - INFO [main:ZKTestCase$1@60] - SUCCEEDED
> testCnxManager
> 2016-07-12 22:35:13,851 [myid:] - INFO [main:ZKTestCase$1@55] - FINISHED
> testCnxManager
> 2016-07-12 22:35:13,862 [myid:] - INFO [main:ZKTestCase$1@50] - STARTING
> testCnxManagerTimeout
> 2016-07-12 22:35:13,862 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11257
> 2016-07-12 22:35:13,862 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11258
> 2016-07-12 22:35:13,862 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11259
> 2016-07-12 22:35:13,862 [myid:] - INFO [main:QuorumPeer$QuorumServer@149] -
> Resolved hostname: 0.0.0.0 to address: /0.0.0.0
> 2016-07-12 22:35:13,862 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11260
> 2016-07-12 22:35:13,862 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11261
> 2016-07-12 22:35:13,862 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11262
> 2016-07-12 22:35:13,862 [myid:] - INFO [main:QuorumPeer$QuorumServer@149] -
> Resolved hostname: 0.0.0.0 to address: /0.0.0.0
> 2016-07-12 22:35:13,863 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11263
> 2016-07-12 22:35:13,863 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11264
> 2016-07-12 22:35:13,863 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11265
> 2016-07-12 22:35:13,863 [myid:] - INFO [main:QuorumPeer$QuorumServer@149] -
> Resolved hostname: 0.0.0.0 to address: /0.0.0.0
> 2016-07-12 22:35:13,863 [myid:] - INFO
> [main:JUnit4ZKTestRunner$LoggedInvokeMethod@53] - RUNNING TEST METHOD
> testCnxManagerTimeout
> 2016-07-12 22:35:13,863 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11266
> 2016-07-12 22:35:13,863 [myid:] - INFO [main:CnxManagerTest@171] - This is
> the dead address I'm trying: 192.0.2.179
> 2016-07-12 22:35:13,863 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11267
> 2016-07-12 22:35:13,863 [myid:] - INFO [main:QuorumPeer$QuorumServer@149] -
> Resolved hostname: 192.0.2.179 to address: /192.0.2.179
> 2016-07-12 22:35:13,864 [myid:] - INFO [main:NIOServerCnxnFactory@89] -
> binding to port 0.0.0.0/0.0.0.0:11261
> 2016-07-12 22:35:13,864 [myid:] - INFO
> [ListenerThread:QuorumCnxManager$Listener@534] - My election bind port:
> /0.0.0.0:11262
> 2016-07-12 22:35:14,000 [myid:] - INFO
> [SessionTracker:SessionTrackerImpl@162] - SessionTrackerImpl exited loop!
> 2016-07-12 22:35:14,310 [myid:] - INFO
> [WorkerSender[myid=2]:FastLeaderElection$Messenger$WorkerSender@438] -
> WorkerSender is down
> 2016-07-12 22:35:14,311 [myid:] - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection$Messenger$WorkerReceiver@407] -
> WorkerReceiver is down
> 2016-07-12 22:35:14,829 [myid:] - INFO
> [/0.0.0.0:11241:QuorumCnxManager$Listener@560] - Leaving listener
> 2016-07-12 22:35:14,840 [myid:] - INFO
> [/0.0.0.0:11244:QuorumCnxManager$Listener@560] - Leaving listener
> 2016-07-12 22:35:14,842 [myid:] - INFO
> [/0.0.0.0:11247:QuorumCnxManager$Listener@560] - Leaving listener
> 2016-07-12 22:35:15,319 [myid:] - INFO
> [WorkerSender[myid=2]:FastLeaderElection$Messenger$WorkerSender@438] -
> WorkerSender is down
> 2016-07-12 22:35:15,320 [myid:] - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection$Messenger$WorkerReceiver@407] -
> WorkerReceiver is down
> 2016-07-12 22:35:16,327 [myid:] - INFO
> [WorkerReceiver[myid=0]:FastLeaderElection$Messenger$WorkerReceiver@407] -
> WorkerReceiver is down
> 2016-07-12 22:35:16,327 [myid:] - INFO
> [WorkerSender[myid=2]:FastLeaderElection$Messenger$WorkerSender@438] -
> WorkerSender is down
> 2016-07-12 22:35:16,327 [myid:] - INFO
> [WorkerSender[myid=0]:FastLeaderElection$Messenger$WorkerSender@438] -
> WorkerSender is down
> 2016-07-12 22:35:16,328 [myid:] - INFO
> [WorkerReceiver[myid=1]:FastLeaderElection$Messenger$WorkerReceiver@407] -
> WorkerReceiver is down
> 2016-07-12 22:35:16,328 [myid:] - INFO
> [WorkerSender[myid=1]:FastLeaderElection$Messenger$WorkerSender@438] -
> WorkerSender is down
> 2016-07-12 22:35:16,328 [myid:] - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection$Messenger$WorkerReceiver@407] -
> WorkerReceiver is down
> 2016-07-12 22:35:18,869 [myid:] - WARN [main:QuorumCnxManager@400] - Cannot
> open channel to 2 at election address /192.0.2.179:11267
> java.net.SocketTimeoutException: connect timed out
> at java.net.PlainSocketImpl.socketConnect(Native Method)
> at
> java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:345)
> at
> java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)
> at
> java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
> at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
> at java.net.Socket.connect(Socket.java:589)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.connectOne(QuorumCnxManager.java:381)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.toSend(QuorumCnxManager.java:354)
> at
> org.apache.zookeeper.server.quorum.CnxManagerTest.testCnxManagerTimeout(CnxManagerTest.java:187)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:483)
> at
> org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:44)
> at
> org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
> at
> org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:41)
> at
> org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:20)
> at
> org.apache.zookeeper.JUnit4ZKTestRunner$LoggedInvokeMethod.evaluate(JUnit4ZKTestRunner.java:55)
> at
> org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28)
> at org.junit.rules.TestWatchman$1.evaluate(TestWatchman.java:48)
> at
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:76)
> at
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50)
> at org.junit.runners.ParentRunner$3.run(ParentRunner.java:193)
> at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:52)
> at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:191)
> at org.junit.runners.ParentRunner.access$000(ParentRunner.java:42)
> at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:184)
> at org.junit.runners.ParentRunner.run(ParentRunner.java:236)
> at junit.framework.JUnit4TestAdapter.run(JUnit4TestAdapter.java:39)
> at
> org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.run(JUnitTestRunner.java:518)
> at
> org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.launch(JUnitTestRunner.java:1052)
> at
> org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.main(JUnitTestRunner.java:906)
> 2016-07-12 22:35:18,870 [myid:] - INFO [main:QuorumPeer$QuorumServer@149] -
> Resolved hostname: 192.0.2.179 to address: /192.0.2.179
> 2016-07-12 22:35:18,870 [myid:] - INFO
> [main:JUnit4ZKTestRunner$LoggedInvokeMethod@58] - Memory used 12750
> 2016-07-12 22:35:18,870 [myid:] - INFO
> [main:JUnit4ZKTestRunner$LoggedInvokeMethod@63] - Number of threads 13
> 2016-07-12 22:35:18,871 [myid:] - INFO
> [main:JUnit4ZKTestRunner$LoggedInvokeMethod@78] - FINISHED TEST METHOD
> testCnxManagerTimeout
> 2016-07-12 22:35:18,871 [myid:] - INFO [main:ZKTestCase$1@60] - SUCCEEDED
> testCnxManagerTimeout
> 2016-07-12 22:35:18,871 [myid:] - INFO [main:ZKTestCase$1@55] - FINISHED
> testCnxManagerTimeout
> 2016-07-12 22:35:18,871 [myid:] - INFO [main:ZKTestCase$1@50] - STARTING
> testCnxManagerSpinLock
> 2016-07-12 22:35:18,872 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11268
> 2016-07-12 22:35:18,872 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11269
> 2016-07-12 22:35:18,872 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11270
> 2016-07-12 22:35:18,872 [myid:] - INFO [main:QuorumPeer$QuorumServer@149] -
> Resolved hostname: 0.0.0.0 to address: /0.0.0.0
> 2016-07-12 22:35:18,872 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11271
> 2016-07-12 22:35:18,872 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11272
> 2016-07-12 22:35:18,872 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11273
> 2016-07-12 22:35:18,873 [myid:] - INFO [main:QuorumPeer$QuorumServer@149] -
> Resolved hostname: 0.0.0.0 to address: /0.0.0.0
> 2016-07-12 22:35:18,873 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11274
> 2016-07-12 22:35:18,873 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11275
> 2016-07-12 22:35:18,873 [myid:] - INFO [main:PortAssignment@32] - assigning
> port 11276
> 2016-07-12 22:35:18,873 [myid:] - INFO [main:QuorumPeer$QuorumServer@149] -
> Resolved hostname: 0.0.0.0 to address: /0.0.0.0
> 2016-07-12 22:35:18,874 [myid:] - INFO
> [main:JUnit4ZKTestRunner$LoggedInvokeMethod@53] - RUNNING TEST METHOD
> testCnxManagerSpinLock
> 2016-07-12 22:35:18,874 [myid:] - INFO [main:NIOServerCnxnFactory@89] -
> binding to port 0.0.0.0/0.0.0.0:11272
> 2016-07-12 22:35:18,875 [myid:] - INFO [main:CnxManagerTest@214] - Election
> port: 11273
> 2016-07-12 22:35:18,875 [myid:] - INFO
> [ListenerThread:QuorumCnxManager$Listener@534] - My election bind port:
> /0.0.0.0:11273
> 2016-07-12 22:35:19,876 [myid:] - INFO
> [/0.0.0.0:11273:QuorumCnxManager$Listener@541] - Received connection request
> /140.211.11.27:37939
> 2016-07-12 22:35:19,876 [myid:] - WARN
> [RecvWorker:2:QuorumCnxManager$RecvWorker@810] - Connection broken for id 2,
> my id = 1, error =
> java.io.IOException: Received packet with invalid packet: -20
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager$RecvWorker.run(QuorumCnxManager.java:797)
> 2016-07-12 22:35:19,877 [myid:] - WARN
> [RecvWorker:2:QuorumCnxManager$RecvWorker@813] - Interrupting SendWorker
> 2016-07-12 22:35:19,877 [myid:] - WARN
> [SendWorker:2:QuorumCnxManager$SendWorker@727] - Interrupted while waiting
> for message on queue
> java.lang.InterruptedException
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2014)
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2088)
> at
> java.util.concurrent.ArrayBlockingQueue.poll(ArrayBlockingQueue.java:418)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.pollSendQueue(QuorumCnxManager.java:879)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.access$500(QuorumCnxManager.java:65)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager$SendWorker.run(QuorumCnxManager.java:715)
> 2016-07-12 22:35:19,877 [myid:] - WARN
> [SendWorker:2:QuorumCnxManager$SendWorker@736] - Send worker leaving thread
> 2016-07-12 22:35:20,876 [myid:] - INFO [main:CnxManagerTest@249] - Socket
> has been closed as expected
> 2016-07-12 22:35:20,876 [myid:] - INFO
> [main:JUnit4ZKTestRunner$LoggedInvokeMethod@58] - Memory used 12944
> 2016-07-12 22:35:20,876 [myid:] - ERROR
> [/0.0.0.0:11273:QuorumCnxManager$Listener@547] - Exception while listening
> java.net.SocketException: Socket closed
> at java.net.PlainSocketImpl.socketAccept(Native Method)
> at
> java.net.AbstractPlainSocketImpl.accept(AbstractPlainSocketImpl.java:404)
> at java.net.ServerSocket.implAccept(ServerSocket.java:545)
> at java.net.ServerSocket.accept(ServerSocket.java:513)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager$Listener.run(QuorumCnxManager.java:539)
> 2016-07-12 22:35:20,877 [myid:] - INFO
> [main:JUnit4ZKTestRunner$LoggedInvokeMethod@63] - Number of threads 14
> 2016-07-12 22:35:20,877 [myid:] - INFO
> [main:JUnit4ZKTestRunner$LoggedInvokeMethod@78] - FINISHED TEST METHOD
> testCnxManagerSpinLock
> 2016-07-12 22:35:20,877 [myid:] - INFO [main:ZKTestCase$1@60] - SUCCEEDED
> testCnxManagerSpinLock
> 2016-07-12 22:35:20,877 [myid:] - INFO [main:ZKTestCase$1@55] - FINISHED
> testCnxManagerSpinLock
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
