[
https://issues.apache.org/jira/browse/ZOOKEEPER-2924?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Andor Molnar updated ZOOKEEPER-2924:
------------------------------------
Description:
>From https://builds.apache.org/job/ZooKeeper_branch34_openjdk7/1682/
Same issue happens in jdk8 and jdk9 builds as well.
Issue has already been fixed by
https://issues.apache.org/jira/browse/ZOOKEEPER-2484 , but I believe that the
root cause here is that test startup / cleanup code is included in the tests
instead of using try-finally block or Before-After methods.
As a consequence, when exception happens during test execution, ZK test server
doesn't get shutdown properly and still listening on the port bound to the test
class.
As mentioned above there could be 2 approaches to address this:
#1 Wrap cleanup code block with finally
#2 Use JUnit's Before-After methods for initialization and cleanup
{{...
[junit] 2017-10-12 15:05:20,135 [myid:] - INFO [ProcessThread(sid:0
cport:11221)::PrepRequestProcessor@653] - Got user-level KeeperException when
processing sessionid:0x104cd7b190c0000 type:create cxid:0x8c zxid:0x8d
txntype:-1 req$
[junit] 2017-10-12 15:05:20,137 [myid:] - INFO [ProcessThread(sid:0
cport:11221)::PrepRequestProcessor@653] - Got user-level KeeperException when
processing sessionid:0x104cd7b190c0000 type:create cxid:0x8d zxid:0x8e
txntype:-1 req$
[junit] 2017-10-12 15:05:20,139 [myid:] - INFO [ProcessThread(sid:0
cport:11221)::PrepRequestProcessor@653] - Got user-level KeeperException when
processing sessionid:0x104cd7b190c0000 type:create cxid:0x8e zxid:0x8f
txntype:-1 req$
[junit] 2017-10-12 15:05:20,142 [myid:] - INFO [ProcessThread(sid:0
cport:11221)::PrepRequestProcessor@653] - Got user-level KeeperException when
processing sessionid:0x104cd7b190c0000 type:create cxid:0x8f zxid:0x90
txntype:-1 req$
[junit] 2017-10-12 15:05:20,144 [myid:] - INFO [ProcessThread(sid:0
cport:11221)::PrepRequestProcessor@653] - Got user-level KeeperException when
processing sessionid:0x104cd7b190c0000 type:create cxid:0x90 zxid:0x91
txntype:-1 req$
[junit] 2017-10-12 15:05:30,479 [myid:] - INFO
[SessionTracker:ZooKeeperServer@354] - Expiring session 0x104cd7b190c0000,
timeout of 6000ms exceeded
[junit] 2017-10-12 15:05:32,996 [myid:] - INFO [ProcessThread(sid:0
cport:11221)::PrepRequestProcessor@653] - Got user-level KeeperException when
processing sessionid:0x104cd7b190c0000 type:ping cxid:0xfffffffffffffffe
zxid:0xfffff$
[junit] 2017-10-12 15:05:24,147 [myid:] - WARN
[main-SendThread(127.0.0.1:11221):ClientCnxn$SendThread@1111] - Client session
timed out, have not heard from server in 4002ms for sessionid 0x104cd7b190c0000
[junit] 2017-10-12 15:05:32,996 [myid:] - INFO
[main-SendThread(127.0.0.1:11221):ClientCnxn$SendThread@1159] - Client session
timed out, have not heard from server in 4002ms for sessionid
0x104cd7b190c0000, closing socket connectio$
[junit] 2017-10-12 15:05:21,479 [myid:] - INFO
[SessionTracker:SessionTrackerImpl@163] - SessionTrackerImpl exited loop!
[junit] 2017-10-12 15:05:32,998 [myid:] - WARN
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:11221:NIOServerCnxn@376] - Unable to read
additional data from client sessionid 0x104cd7b190c0000, likely client has
closed socket
[junit] 2017-10-12 15:05:33,067 [myid:] - INFO
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:11221:NIOServerCnxn@1040] - Closed socket
connection for client /127.0.0.1:45735 which had sessionid 0x104cd7b190c0000
[junit] 2017-10-12 15:05:32,996 [myid:] - INFO [ProcessThread(sid:0
cport:11221)::PrepRequestProcessor@487] - Processed session termination for
sessionid: 0x104cd7b190c0000
[junit] 2017-10-12 15:05:33,889 [myid:] - INFO [main:ZooKeeper@687] -
Session: 0x104cd7b190c0000 closed
[junit] 2017-10-12 15:05:33,890 [myid:] - INFO
[main-EventThread:ClientCnxn$EventThread@520] - EventThread shut down for
session: 0x104cd7b190c0000
[junit] 2017-10-12 15:05:33,891 [myid:] - INFO
[main:JUnit4ZKTestRunner$LoggedInvokeMethod@74] - TEST METHOD FAILED
testRestoreWithTransactionErrors
[junit] org.apache.zookeeper.KeeperException$ConnectionLossException:
KeeperErrorCode = ConnectionLoss for /invaliddir/test-
[junit] at
org.apache.zookeeper.KeeperException.create(KeeperException.java:102)
[junit] at
org.apache.zookeeper.KeeperException.create(KeeperException.java:54)
[junit] at org.apache.zookeeper.ZooKeeper.create(ZooKeeper.java:786)
[junit] at
org.apache.zookeeper.test.LoadFromLogTest.testRestoreWithTransactionErrors(LoadFromLogTest.java:368)
[junit] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[junit] at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
[junit] at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[junit] at java.lang.reflect.Method.invoke(Method.java:606)
[junit] at
org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:44)
[junit] at
org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
[junit] at
org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:41)
[junit] at
org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:20)
[junit] at
org.apache.zookeeper.JUnit4ZKTestRunner$LoggedInvokeMethod.evaluate(JUnit4ZKTestRunner.java:55)
[junit] at
org.junit.rules.TestWatchman$1.evaluate(TestWatchman.java:48)
[junit] at
org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:76)
[junit] at
org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50)
[junit] at org.junit.runners.ParentRunner$3.run(ParentRunner.java:193)
[junit] at
org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:52)
[junit] at
org.junit.runners.ParentRunner.runChildren(ParentRunner.java:191)
[junit] at
org.junit.runners.ParentRunner.access$000(ParentRunner.java:42)
[junit] at
org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:184)
[junit] at org.junit.runners.ParentRunner.run(ParentRunner.java:236)
[junit] at
junit.framework.JUnit4TestAdapter.run(JUnit4TestAdapter.java:39)
[junit] at
org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.run(JUnitTestRunner.java:535)
[junit] at
org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.launch(JUnitTestRunner.java:1182)
[junit] at
org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.main(JUnitTestRunner.java:1033)}}
was:
>From https://builds.apache.org/job/ZooKeeper_branch34_openjdk7/1682/
Same issue happens in jdk8 and jdk9 builds as well.
Issue has already been fixed by
https://issues.apache.org/jira/browse/ZOOKEEPER-2484 , but I believe that the
root cause here is that test startup / cleanup code is included in the tests
instead of using try-finally block or Before-After methods.
As a consequence, when exception happens during test execution, ZK test server
doesn't get shutdown properly and still listening on the port bound to the test
class.
As mentioned above there could be 2 approaches to address this:
#1 Wrap cleanup code block with finally
#2 Use JUnit's Before-After methods for initialization and cleanup
{{ ...
[junit] 2017-10-12 15:05:20,135 [myid:] - INFO [ProcessThread(sid:0
cport:11221)::PrepRequestProcessor@653] - Got user-level KeeperException when
processing sessionid:0x104cd7b190c0000 type:create cxid:0x8c zxid:0x8d
txntype:-1 req$
[junit] 2017-10-12 15:05:20,137 [myid:] - INFO [ProcessThread(sid:0
cport:11221)::PrepRequestProcessor@653] - Got user-level KeeperException when
processing sessionid:0x104cd7b190c0000 type:create cxid:0x8d zxid:0x8e
txntype:-1 req$
[junit] 2017-10-12 15:05:20,139 [myid:] - INFO [ProcessThread(sid:0
cport:11221)::PrepRequestProcessor@653] - Got user-level KeeperException when
processing sessionid:0x104cd7b190c0000 type:create cxid:0x8e zxid:0x8f
txntype:-1 req$
[junit] 2017-10-12 15:05:20,142 [myid:] - INFO [ProcessThread(sid:0
cport:11221)::PrepRequestProcessor@653] - Got user-level KeeperException when
processing sessionid:0x104cd7b190c0000 type:create cxid:0x8f zxid:0x90
txntype:-1 req$
[junit] 2017-10-12 15:05:20,144 [myid:] - INFO [ProcessThread(sid:0
cport:11221)::PrepRequestProcessor@653] - Got user-level KeeperException when
processing sessionid:0x104cd7b190c0000 type:create cxid:0x90 zxid:0x91
txntype:-1 req$
[junit] 2017-10-12 15:05:30,479 [myid:] - INFO
[SessionTracker:ZooKeeperServer@354] - Expiring session 0x104cd7b190c0000,
timeout of 6000ms exceeded
[junit] 2017-10-12 15:05:32,996 [myid:] - INFO [ProcessThread(sid:0
cport:11221)::PrepRequestProcessor@653] - Got user-level KeeperException when
processing sessionid:0x104cd7b190c0000 type:ping cxid:0xfffffffffffffffe
zxid:0xfffff$
[junit] 2017-10-12 15:05:24,147 [myid:] - WARN
[main-SendThread(127.0.0.1:11221):ClientCnxn$SendThread@1111] - Client session
timed out, have not heard from server in 4002ms for sessionid 0x104cd7b190c0000
[junit] 2017-10-12 15:05:32,996 [myid:] - INFO
[main-SendThread(127.0.0.1:11221):ClientCnxn$SendThread@1159] - Client session
timed out, have not heard from server in 4002ms for sessionid
0x104cd7b190c0000, closing socket connectio$
[junit] 2017-10-12 15:05:21,479 [myid:] - INFO
[SessionTracker:SessionTrackerImpl@163] - SessionTrackerImpl exited loop!
[junit] 2017-10-12 15:05:32,998 [myid:] - WARN
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:11221:NIOServerCnxn@376] - Unable to read
additional data from client sessionid 0x104cd7b190c0000, likely client has
closed socket
[junit] 2017-10-12 15:05:33,067 [myid:] - INFO
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:11221:NIOServerCnxn@1040] - Closed socket
connection for client /127.0.0.1:45735 which had sessionid 0x104cd7b190c0000
[junit] 2017-10-12 15:05:32,996 [myid:] - INFO [ProcessThread(sid:0
cport:11221)::PrepRequestProcessor@487] - Processed session termination for
sessionid: 0x104cd7b190c0000
[junit] 2017-10-12 15:05:33,889 [myid:] - INFO [main:ZooKeeper@687] -
Session: 0x104cd7b190c0000 closed
[junit] 2017-10-12 15:05:33,890 [myid:] - INFO
[main-EventThread:ClientCnxn$EventThread@520] - EventThread shut down for
session: 0x104cd7b190c0000
[junit] 2017-10-12 15:05:33,891 [myid:] - INFO
[main:JUnit4ZKTestRunner$LoggedInvokeMethod@74] - TEST METHOD FAILED
testRestoreWithTransactionErrors
[junit] org.apache.zookeeper.KeeperException$ConnectionLossException:
KeeperErrorCode = ConnectionLoss for /invaliddir/test-
[junit] at
org.apache.zookeeper.KeeperException.create(KeeperException.java:102)
[junit] at
org.apache.zookeeper.KeeperException.create(KeeperException.java:54)
[junit] at org.apache.zookeeper.ZooKeeper.create(ZooKeeper.java:786)
[junit] at
org.apache.zookeeper.test.LoadFromLogTest.testRestoreWithTransactionErrors(LoadFromLogTest.java:368)
[junit] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[junit] at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
[junit] at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[junit] at java.lang.reflect.Method.invoke(Method.java:606)
[junit] at
org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:44)
[junit] at
org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
[junit] at
org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:41)
[junit] at
org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:20)
[junit] at
org.apache.zookeeper.JUnit4ZKTestRunner$LoggedInvokeMethod.evaluate(JUnit4ZKTestRunner.java:55)
[junit] at
org.junit.rules.TestWatchman$1.evaluate(TestWatchman.java:48)
[junit] at
org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:76)
[junit] at
org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50)
[junit] at org.junit.runners.ParentRunner$3.run(ParentRunner.java:193)
[junit] at
org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:52)
[junit] at
org.junit.runners.ParentRunner.runChildren(ParentRunner.java:191)
[junit] at
org.junit.runners.ParentRunner.access$000(ParentRunner.java:42)
[junit] at
org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:184)
[junit] at org.junit.runners.ParentRunner.run(ParentRunner.java:236)
[junit] at
junit.framework.JUnit4TestAdapter.run(JUnit4TestAdapter.java:39)
[junit] at
org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.run(JUnitTestRunner.java:535)
[junit] at
org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.launch(JUnitTestRunner.java:1182)
[junit] at
org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.main(JUnitTestRunner.java:1033)}}
> Flaky Test:
> org.apache.zookeeper.test.LoadFromLogTest.testRestoreWithTransactionErrors
> --------------------------------------------------------------------------------------
>
> Key: ZOOKEEPER-2924
> URL: https://issues.apache.org/jira/browse/ZOOKEEPER-2924
> Project: ZooKeeper
> Issue Type: Bug
> Components: server, tests
> Reporter: Andor Molnar
> Assignee: Andor Molnar
> Labels: flaky, flaky-test
> Fix For: 3.4.12
>
>
> From https://builds.apache.org/job/ZooKeeper_branch34_openjdk7/1682/
> Same issue happens in jdk8 and jdk9 builds as well.
> Issue has already been fixed by
> https://issues.apache.org/jira/browse/ZOOKEEPER-2484 , but I believe that the
> root cause here is that test startup / cleanup code is included in the tests
> instead of using try-finally block or Before-After methods.
> As a consequence, when exception happens during test execution, ZK test
> server doesn't get shutdown properly and still listening on the port bound to
> the test class.
> As mentioned above there could be 2 approaches to address this:
> #1 Wrap cleanup code block with finally
> #2 Use JUnit's Before-After methods for initialization and cleanup
> {{...
> [junit] 2017-10-12 15:05:20,135 [myid:] - INFO [ProcessThread(sid:0
> cport:11221)::PrepRequestProcessor@653] - Got user-level KeeperException when
> processing sessionid:0x104cd7b190c0000 type:create cxid:0x8c zxid:0x8d
> txntype:-1 req$
> [junit] 2017-10-12 15:05:20,137 [myid:] - INFO [ProcessThread(sid:0
> cport:11221)::PrepRequestProcessor@653] - Got user-level KeeperException when
> processing sessionid:0x104cd7b190c0000 type:create cxid:0x8d zxid:0x8e
> txntype:-1 req$
> [junit] 2017-10-12 15:05:20,139 [myid:] - INFO [ProcessThread(sid:0
> cport:11221)::PrepRequestProcessor@653] - Got user-level KeeperException when
> processing sessionid:0x104cd7b190c0000 type:create cxid:0x8e zxid:0x8f
> txntype:-1 req$
> [junit] 2017-10-12 15:05:20,142 [myid:] - INFO [ProcessThread(sid:0
> cport:11221)::PrepRequestProcessor@653] - Got user-level KeeperException when
> processing sessionid:0x104cd7b190c0000 type:create cxid:0x8f zxid:0x90
> txntype:-1 req$
> [junit] 2017-10-12 15:05:20,144 [myid:] - INFO [ProcessThread(sid:0
> cport:11221)::PrepRequestProcessor@653] - Got user-level KeeperException when
> processing sessionid:0x104cd7b190c0000 type:create cxid:0x90 zxid:0x91
> txntype:-1 req$
> [junit] 2017-10-12 15:05:30,479 [myid:] - INFO
> [SessionTracker:ZooKeeperServer@354] - Expiring session 0x104cd7b190c0000,
> timeout of 6000ms exceeded
> [junit] 2017-10-12 15:05:32,996 [myid:] - INFO [ProcessThread(sid:0
> cport:11221)::PrepRequestProcessor@653] - Got user-level KeeperException when
> processing sessionid:0x104cd7b190c0000 type:ping cxid:0xfffffffffffffffe
> zxid:0xfffff$
> [junit] 2017-10-12 15:05:24,147 [myid:] - WARN
> [main-SendThread(127.0.0.1:11221):ClientCnxn$SendThread@1111] - Client
> session timed out, have not heard from server in 4002ms for sessionid
> 0x104cd7b190c0000
> [junit] 2017-10-12 15:05:32,996 [myid:] - INFO
> [main-SendThread(127.0.0.1:11221):ClientCnxn$SendThread@1159] - Client
> session timed out, have not heard from server in 4002ms for sessionid
> 0x104cd7b190c0000, closing socket connectio$
> [junit] 2017-10-12 15:05:21,479 [myid:] - INFO
> [SessionTracker:SessionTrackerImpl@163] - SessionTrackerImpl exited loop!
> [junit] 2017-10-12 15:05:32,998 [myid:] - WARN
> [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:11221:NIOServerCnxn@376] - Unable to
> read additional data from client sessionid 0x104cd7b190c0000, likely client
> has closed socket
> [junit] 2017-10-12 15:05:33,067 [myid:] - INFO
> [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:11221:NIOServerCnxn@1040] - Closed
> socket connection for client /127.0.0.1:45735 which had sessionid
> 0x104cd7b190c0000
> [junit] 2017-10-12 15:05:32,996 [myid:] - INFO [ProcessThread(sid:0
> cport:11221)::PrepRequestProcessor@487] - Processed session termination for
> sessionid: 0x104cd7b190c0000
> [junit] 2017-10-12 15:05:33,889 [myid:] - INFO [main:ZooKeeper@687] -
> Session: 0x104cd7b190c0000 closed
> [junit] 2017-10-12 15:05:33,890 [myid:] - INFO
> [main-EventThread:ClientCnxn$EventThread@520] - EventThread shut down for
> session: 0x104cd7b190c0000
> [junit] 2017-10-12 15:05:33,891 [myid:] - INFO
> [main:JUnit4ZKTestRunner$LoggedInvokeMethod@74] - TEST METHOD FAILED
> testRestoreWithTransactionErrors
> [junit] org.apache.zookeeper.KeeperException$ConnectionLossException:
> KeeperErrorCode = ConnectionLoss for /invaliddir/test-
> [junit] at
> org.apache.zookeeper.KeeperException.create(KeeperException.java:102)
> [junit] at
> org.apache.zookeeper.KeeperException.create(KeeperException.java:54)
> [junit] at org.apache.zookeeper.ZooKeeper.create(ZooKeeper.java:786)
> [junit] at
> org.apache.zookeeper.test.LoadFromLogTest.testRestoreWithTransactionErrors(LoadFromLogTest.java:368)
> [junit] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native
> Method)
> [junit] at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
> [junit] at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> [junit] at java.lang.reflect.Method.invoke(Method.java:606)
> [junit] at
> org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:44)
> [junit] at
> org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
> [junit] at
> org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:41)
> [junit] at
> org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:20)
> [junit] at
> org.apache.zookeeper.JUnit4ZKTestRunner$LoggedInvokeMethod.evaluate(JUnit4ZKTestRunner.java:55)
> [junit] at
> org.junit.rules.TestWatchman$1.evaluate(TestWatchman.java:48)
> [junit] at
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:76)
> [junit] at
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50)
> [junit] at
> org.junit.runners.ParentRunner$3.run(ParentRunner.java:193)
> [junit] at
> org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:52)
> [junit] at
> org.junit.runners.ParentRunner.runChildren(ParentRunner.java:191)
> [junit] at
> org.junit.runners.ParentRunner.access$000(ParentRunner.java:42)
> [junit] at
> org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:184)
> [junit] at org.junit.runners.ParentRunner.run(ParentRunner.java:236)
> [junit] at
> junit.framework.JUnit4TestAdapter.run(JUnit4TestAdapter.java:39)
> [junit] at
> org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.run(JUnitTestRunner.java:535)
> [junit] at
> org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.launch(JUnitTestRunner.java:1182)
> [junit] at
> org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.main(JUnitTestRunner.java:1033)}}
--
This message was sent by Atlassian JIRA
(v6.4.14#64029)
