Return-Path: X-Original-To: archive-asf-public-internal@cust-asf2.ponee.io Delivered-To: archive-asf-public-internal@cust-asf2.ponee.io Received: from cust-asf.ponee.io (cust-asf.ponee.io [163.172.22.183]) by cust-asf2.ponee.io (Postfix) with ESMTP id 35CB5200D29 for ; Thu, 26 Oct 2017 19:45:07 +0200 (CEST) Received: by cust-asf.ponee.io (Postfix) id 3458C1609E8; Thu, 26 Oct 2017 17:45:07 +0000 (UTC) Delivered-To: archive-asf-public@cust-asf.ponee.io Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by cust-asf.ponee.io (Postfix) with SMTP id 2AD981609E5 for ; Thu, 26 Oct 2017 19:45:06 +0200 (CEST) Received: (qmail 6017 invoked by uid 500); 26 Oct 2017 17:45:05 -0000 Mailing-List: contact dev-help@zookeeper.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@zookeeper.apache.org Delivered-To: mailing list dev@zookeeper.apache.org Received: (qmail 6006 invoked by uid 99); 26 Oct 2017 17:45:05 -0000 Received: from pnap-us-west-generic-nat.apache.org (HELO spamd3-us-west.apache.org) (209.188.14.142) by apache.org (qpsmtpd/0.29) with ESMTP; Thu, 26 Oct 2017 17:45:05 +0000 Received: from localhost (localhost [127.0.0.1]) by spamd3-us-west.apache.org (ASF Mail Server at spamd3-us-west.apache.org) with ESMTP id 7337E180874 for ; Thu, 26 Oct 2017 17:45:04 +0000 (UTC) X-Virus-Scanned: Debian amavisd-new at spamd3-us-west.apache.org X-Spam-Flag: NO X-Spam-Score: -99.202 X-Spam-Level: X-Spam-Status: No, score=-99.202 tagged_above=-999 required=6.31 tests=[KAM_ASCII_DIVIDERS=0.8, RP_MATCHES_RCVD=-0.001, SPF_PASS=-0.001, USER_IN_WHITELIST=-100] autolearn=disabled Received: from mx1-lw-us.apache.org ([10.40.0.8]) by localhost (spamd3-us-west.apache.org [10.40.0.10]) (amavisd-new, port 10024) with ESMTP id GrpVbhzhVqcN for ; Thu, 26 Oct 2017 17:45:02 +0000 (UTC) Received: from mailrelay1-us-west.apache.org (mailrelay1-us-west.apache.org [209.188.14.139]) by mx1-lw-us.apache.org (ASF Mail Server at mx1-lw-us.apache.org) with ESMTP id 9D24A5FE18 for ; Thu, 26 Oct 2017 17:45:01 +0000 (UTC) Received: from jira-lw-us.apache.org (unknown [207.244.88.139]) by mailrelay1-us-west.apache.org (ASF Mail Server at mailrelay1-us-west.apache.org) with ESMTP id 06894E2573 for ; Thu, 26 Oct 2017 17:45:00 +0000 (UTC) Received: from jira-lw-us.apache.org (localhost [127.0.0.1]) by jira-lw-us.apache.org (ASF Mail Server at jira-lw-us.apache.org) with ESMTP id A76C9212FD for ; Thu, 26 Oct 2017 17:45:00 +0000 (UTC) Date: Thu, 26 Oct 2017 17:45:00 +0000 (UTC) From: "Abraham Fine (JIRA)" To: dev@zookeeper.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Commented] (ZOOKEEPER-2924) Flaky Test: org.apache.zookeeper.test.LoadFromLogTest.testRestoreWithTransactionErrors MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 7bit X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 archived-at: Thu, 26 Oct 2017 17:45:07 -0000 [ https://issues.apache.org/jira/browse/ZOOKEEPER-2924?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16220882#comment-16220882 ] Abraham Fine commented on ZOOKEEPER-2924: ----------------------------------------- I think solution #2 would be the way to go. It is inline with what we do in other tests. > 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 > Test where original issue happens: > {noformat} > ... > [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) > {noformat} > Test #2 where port is already in use: > {noformat} > [junit] 2017-10-12 15:05:33,899 [myid:] - INFO [main:ZKTestCase$1@59] - STARTING testReloadSnapshotWithMissingParent > [junit] 2017-10-12 15:05:33,899 [myid:] - INFO [main:JUnit4ZKTestRunner$LoggedInvokeMethod@53] - RUNNING TEST METHOD testReloadSnapshotWithMissingParent > [junit] 2017-10-12 15:05:33,900 [myid:] - INFO [main:ZooKeeperServer@173] - Created server with tickTime 3000 minSessionTimeout 6000 maxSessionTimeout 60000 datadir /home/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_openjdk7/$ > [junit] 2017-10-12 15:05:33,900 [myid:] - INFO [main:ServerCnxnFactory@117] - Using org.apache.zookeeper.server.NIOServerCnxnFactory as server connection factory > [junit] 2017-10-12 15:05:33,900 [myid:] - INFO [main:NIOServerCnxnFactory@89] - binding to port 0.0.0.0/0.0.0.0:11221 > [junit] 2017-10-12 15:05:33,901 [myid:] - INFO [main:JUnit4ZKTestRunner$LoggedInvokeMethod@74] - TEST METHOD FAILED testReloadSnapshotWithMissingParent > [junit] java.net.BindException: Address already in use > [junit] at sun.nio.ch.Net.bind0(Native Method) > [junit] at sun.nio.ch.Net.bind(Net.java:463) > [junit] at sun.nio.ch.Net.bind(Net.java:455) > [junit] at sun.nio.ch.ServerSocketChannelImpl.bind(ServerSocketChannelImpl.java:223) > [junit] at sun.nio.ch.ServerSocketAdaptor.bind(ServerSocketAdaptor.java:74) > [junit] at sun.nio.ch.ServerSocketAdaptor.bind(ServerSocketAdaptor.java:67) > [junit] at org.apache.zookeeper.server.NIOServerCnxnFactory.configure(NIOServerCnxnFactory.java:90) > [junit] at org.apache.zookeeper.server.ServerCnxnFactory.createFactory(ServerCnxnFactory.java:137) > [junit] at org.apache.zookeeper.server.ServerCnxnFactory.createFactory(ServerCnxnFactory.java:130) > [junit] at org.apache.zookeeper.test.LoadFromLogTest.testReloadSnapshotWithMissingParent(LoadFromLogTest.java:412) > [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) > {noformat} -- This message was sent by Atlassian JIRA (v6.4.14#64029)