[ZOOKEEPER-1862] ServerCnxnTest.testServerCnxnExpiry is intermittently failing

• Type: Bug
• Status: Resolved
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 3.5.0
• Fix Version/s: 3.5.0
• Component/s: tests
• Assignee: Rakesh Radhakrishnan
• Reporter: Rakesh Radhakrishnan
• Created: 13/Jan/14 03:50
• Updated: 16/Mar/14 17:53
• Resolved: 14/Mar/14 23:11

Description

ServerCnxnTest#testServerCnxnExpiry test case is failing in the trunk build with the following exception

    [junit] 2014-01-11 10:13:07,696 [myid:] - INFO  [NIOServerCxnFactory.AcceptThread:0.0.0.0/0.0.0.0:11221:NIOServerCnxnFactory$AcceptThread@296] - Accepted socket connection from /127.0.0.1:63930
    [junit] 2014-01-11 10:13:09,000 [myid:] - INFO  [ConnnectionExpirer:NIOServerCnxn@1006] - Closed socket connection for client /127.0.0.1:63930 (no session established for client)
    [junit] 2014-01-11 10:13:10,697 [myid:] - INFO  [main:JUnit4ZKTestRunner$LoggedInvokeMethod@62] - TEST METHOD FAILED testServerCnxnExpiry
    [junit] java.net.SocketException: Software caused connection abort: recv failed
    [junit] 	at java.net.SocketInputStream.socketRead0(Native Method)
    [junit] 	at java.net.SocketInputStream.read(SocketInputStream.java:150)
    [junit] 	at java.net.SocketInputStream.read(SocketInputStream.java:121)
    [junit] 	at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:283)
    [junit] 	at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:325)
    [junit] 	at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:177)
    [junit] 	at java.io.InputStreamReader.read(InputStreamReader.java:184)
    [junit] 	at java.io.BufferedReader.fill(BufferedReader.java:154)
    [junit] 	at java.io.BufferedReader.readLine(BufferedReader.java:317)
    [junit] 	at java.io.BufferedReader.readLine(BufferedReader.java:382)
    [junit] 	at org.apache.zookeeper.test.ServerCnxnTest.send4LetterWord(ServerCnxnTest.java:105)
    [junit] 	at org.apache.zookeeper.test.ServerCnxnTest.sendRequest(ServerCnxnTest.java:77)
    [junit] 	at org.apache.zookeeper.test.ServerCnxnTest.testServerCnxnExpiry(ServerCnxnTest.java:64)
    [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:601)
    [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:52)
    [junit] 	at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28)
    [junit] 	at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:31)
    [junit] 	at org.junit.rules.TestWatchman$1.evaluate(TestWatchman.java:52)
    [junit] 	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:263)
    [junit] 	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:69)
    [junit] 	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:48)
    [junit] 	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:231)
    [junit] 	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:60)
    [junit] 	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:229)
    [junit] 	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:50)
    [junit] 	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:222)
    [junit] 	at org.junit.runners.ParentRunner.run(ParentRunner.java:292)
    [junit] 	at junit.framework.JUnit4TestAdapter.run(JUnit4TestAdapter.java:39)
    [junit] 	at org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.run(JUnitTestRunner.java:518)
    [junit] 	at org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.launch(JUnitTestRunner.java:1052)
    [junit] 	at org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.main(JUnitTestRunner.java:906)
    

When analyzing the possible cause of the failure is:
During connection expiry server will close the socket channel connection. After the socket closure, when the client tries to read a line of text will throw java.net.SocketException.

In the failure scenario the testcase has established a socket connection and entering into the sleep. In the meantime the server side expiration would happen and closing the socket channel. Assume after the socket closure the testcase is trying to read the text using the previously established socket and is resulting in SocketException. There is a race between the reading the socket in the client side and socket closure in server side.

NIOServerCnxn#closeSock is closing the socket channel.
 sock.socket().shutdownOutput();
 sock.socket().shutdownInput();
 sock.socket().close();
 sock.close();

Issue Links

• is duplicated by: ZOOKEEPER-1650 testServerCnxnExpiry failing consistently on solaris apache jenkins