[
https://issues.apache.org/jira/browse/ZOOKEEPER-1477?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13413501#comment-13413501
]
Diego Oliveira commented on ZOOKEEPER-1477:
-------------------------------------------
I did some logging to look up what is happening. The idea was to log all bytes
send from client to server and the other way back. Running in the working
environment(jdk6) the math was just fine, all bytes send was read BUT with jdk7
in the middle of the communication the server stop to read the data.
Here is the log from the good communication:
{code}
2012-07-13 01:41:32,542 [myid:] - TRACE
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:11221:NIOServerCnxn@378] - Readed from
cleint, size[4] values [java.nio.HeapByteBuffer[pos=4 lim=4 cap=4]]
2012-07-13 01:41:32,544 [myid:] - INFO
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:11221:NIOServerCnxn@839] - Processing
stat command from /127.0.0.1:57304
2012-07-13 01:41:32,546 [myid:] - INFO
[Thread-4:NIOServerCnxn$StatCommand@673] - Stat command output
2012-07-13 01:41:32,546 [myid:] - TRACE [Thread-4:NIOServerCnxn@189] - Writting
to client, size[239] values [[90, 111, 111, 107, 101, 101, 112, 101, 114, 32,
118, 101, 114, 115, 105, 111, 110, 58, 32, 51, 46, 53, 46, 48, 45, 49, 51, 54,
49, 48, 51, 51, 44, 32, 98, 117, 105, 108, 116, 32, 111, 110, 32, 48, 55, 47,
49, 51, 47, 50, 48, 49, 50, 32, 48, 51, 58, 52, 50, 32, 71, 77, 84, 10, 67,
108, 105, 101, 110, 116, 115, 58, 10, 32, 47, 49, 50, 55, 46, 48, 46, 48, 46,
49, 58, 53, 55, 51, 48, 52, 91, 48, 93, 40, 113, 117, 101, 117, 101, 100, 61,
48, 44, 114, 101, 99, 118, 101, 100, 61, 49, 44, 115, 101, 110, 116, 61, 48,
41, 10, 10, 76, 97, 116, 101, 110, 99, 121, 32, 109, 105, 110, 47, 97, 118,
103, 47, 109, 97, 120, 58, 32, 48, 47, 48, 47, 48, 10, 82, 101, 99, 101, 105,
118, 101, 100, 58, 32, 49, 10, 83, 101, 110, 116, 58, 32, 48, 10, 67, 111, 110,
110, 101, 99, 116, 105, 111, 110, 115, 58, 32, 49, 10, 79, 117, 116, 115, 116,
97, 110, 100, 105, 110, 103, 58, 32, 48, 10, 90, 120, 105, 100, 58, 32, 48,
120, 48, 10, 77, 111, 100, 101, 58, 32, 115, 116, 97, 110, 100, 97, 108, 111,
110, 101, 10, 78, 111, 100, 101, 32, 99, 111, 117, 110, 116, 58, 32, 52, 10]]
2012-07-13 01:41:32,548 [myid:] - INFO [Thread-4:NIOServerCnxn@1019] - Closed
socket connection for client /127.0.0.1:57304 (no session established for
client)
2012-07-13 01:41:32,549 [myid:] - DEBUG [Thread-4:NIOServerCnxn@1043] -
ignoring exception during input shutdown
2012-07-13 01:41:32,674 [myid:] - TRACE
[main-SendThread(localhost:11221):ClientCnxnSocketNIO@111] - Write to server,
size[49] values [[0, 0, 0, 45, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 117,
48, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 16, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0,
0, 0, 0, 0]]
2012-07-13 01:41:32,775 [myid:] - TRACE
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:11221:NIOServerCnxn@378] - Readed from
cleint, size[4] values [java.nio.HeapByteBuffer[pos=4 lim=4 cap=4]]
2012-07-13 01:41:32,776 [myid:] - TRACE
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:11221:NIOServerCnxn@378] - Readed from
cleint, size[45] values [java.nio.HeapByteBuffer[pos=45 lim=45 cap=45]]
2012-07-13 01:41:32,788 [myid:] - TRACE [SyncThread:0:NIOServerCnxn@189] -
Writting to client, size[41] values [[0, 0, 0, 37, 0, 0, 0, 0, 0, 0, 117, 48,
1, 56, 126, -92, 74, 5, 0, 0, 0, 0, 0, 16, -47, -36, -106, 57, -118, -4, -32,
-86, -105, 78, -24, 7, -29, 104, 91, 15, 0]]
2012-07-13 01:41:32,977 [myid:] - TRACE
[main-SendThread(localhost:11221):ClientCnxnSocketNIO@133] - Readed from
server, size[4] values [java.nio.DirectByteBuffer[pos=4 lim=4 cap=4]]
2012-07-13 01:41:33,078 [myid:] - TRACE
[main-SendThread(localhost:11221):ClientCnxnSocketNIO@133] - Readed from
server, size[37] values [java.nio.HeapByteBuffer[pos=37 lim=37 cap=37]]
2012-07-13 01:41:33,184 [myid:] - TRACE
[main-SendThread(localhost:11221):ClientCnxnSocketNIO@111] - Write to server,
size[29] values [[0, 0, 0, 25, 0, 0, 0, 1, 0, 0, 0, 5, 0, 0, 0, 1, 47, 0, 0, 0,
4, 115, 111, 109, 101, -1, -1, -1, -1]]
*** This is OK in the jdk6, in the jdk7 the communication hangs up.
2012-07-13 01:41:33,285 [myid:] - TRACE
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:11221:NIOServerCnxn@378] - Readed from
cleint, size[4] values [java.nio.HeapByteBuffer[pos=4 lim=4 cap=4]]
2012-07-13 01:41:33,286 [myid:] - TRACE
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:11221:NIOServerCnxn@378] - Readed from
cleint, size[25] values [java.nio.HeapByteBuffer[pos=25 lim=25 cap=25]]
2012-07-13 01:41:33,289 [myid:] - TRACE [SyncThread:0:NIOServerCnxn@189] -
Writting to client, size[88] values [[0, 0, 0, 84, 0, 0, 0, 1, 0, 0, 0, 0, 0,
0, 0, 2, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 2, 0, 0, 0,
0, 0, 0, 0, 0, 0, 0, 1, 56, 126, -92, 77, 102, 0, 0, 0, 1, -1, -1, -1, -1, 0,
0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 4, 0, 0, 0, 1, 0, 0, 0, 0, 0, 0, 0,
0]]
2012-07-13 01:41:33,391 [myid:] - TRACE
[main-SendThread(localhost:11221):ClientCnxnSocketNIO@133] - Readed from
server, size[4] values [java.nio.DirectByteBuffer[pos=4 lim=4 cap=4]]
2012-07-13 01:41:33,492 [myid:] - TRACE
[main-SendThread(localhost:11221):ClientCnxnSocketNIO@133] - Readed from
server, size[84] values [java.nio.HeapByteBuffer[pos=84 lim=84 cap=84]]
2012-07-13 01:41:33,595 [myid:] - TRACE
[main-SendThread(localhost:11221):ClientCnxnSocketNIO@111] - Write to server,
size[57] values [[0, 0, 0, 53, 0, 0, 0, 2, 0, 0, 0, 1, 0, 0, 0, 2, 47, 97, 0,
0, 0, 4, 115, 111, 109, 101, 0, 0, 0, 1, 0, 0, 0, 31, 0, 0, 0, 5, 119, 111,
114, 108, 100, 0, 0, 0, 6, 97, 110, 121, 111, 110, 101, 0, 0, 0, 0]]
{code}
Jdk7 log.
{code}
2012-07-13 01:49:37,588 [myid:] - TRACE
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:11221:NIOServerCnxn@378] - Readed from
cleint, size[4] values [java.nio.HeapByteBuffer[pos=4 lim=4 cap=4]]
2012-07-13 01:49:37,591 [myid:] - INFO
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:11221:NIOServerCnxn@839] - Processing
stat command from /127.0.0.1:57445
2012-07-13 01:49:37,594 [myid:] - INFO
[Thread-2:NIOServerCnxn$StatCommand@673] - Stat command output
2012-07-13 01:49:37,595 [myid:] - TRACE [Thread-2:NIOServerCnxn@189] - Writting
to client, size[239] values [[90, 111, 111, 107, 101, 101, 112, 101, 114, 32,
118, 101, 114, 115, 105, 111, 110, 58, 32, 51, 46, 53, 46, 48, 45, 49, 51, 54,
49, 48, 51, 51, 44, 32, 98, 117, 105, 108, 116, 32, 111, 110, 32, 48, 55, 47,
49, 51, 47, 50, 48, 49, 50, 32, 48, 51, 58, 52, 50, 32, 71, 77, 84, 10, 67,
108, 105, 101, 110, 116, 115, 58, 10, 32, 47, 49, 50, 55, 46, 48, 46, 48, 46,
49, 58, 53, 55, 52, 52, 53, 91, 48, 93, 40, 113, 117, 101, 117, 101, 100, 61,
48, 44, 114, 101, 99, 118, 101, 100, 61, 49, 44, 115, 101, 110, 116, 61, 48,
41, 10, 10, 76, 97, 116, 101, 110, 99, 121, 32, 109, 105, 110, 47, 97, 118,
103, 47, 109, 97, 120, 58, 32, 48, 47, 48, 47, 48, 10, 82, 101, 99, 101, 105,
118, 101, 100, 58, 32, 49, 10, 83, 101, 110, 116, 58, 32, 48, 10, 67, 111, 110,
110, 101, 99, 116, 105, 111, 110, 115, 58, 32, 49, 10, 79, 117, 116, 115, 116,
97, 110, 100, 105, 110, 103, 58, 32, 48, 10, 90, 120, 105, 100, 58, 32, 48,
120, 48, 10, 77, 111, 100, 101, 58, 32, 115, 116, 97, 110, 100, 97, 108, 111,
110, 101, 10, 78, 111, 100, 101, 32, 99, 111, 117, 110, 116, 58, 32, 52, 10]]
2012-07-13 01:49:37,596 [myid:] - INFO [Thread-2:NIOServerCnxn@1019] - Closed
socket connection for client /127.0.0.1:57445 (no session established for
client)
2012-07-13 01:49:37,723 [myid:] - TRACE
[main-SendThread(localhost:11221):ClientCnxnSocketNIO@111] - Write to server,
size[49] values [[0, 0, 0, 45, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 117,
48, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 16, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0,
0, 0, 0, 0]]
2012-07-13 01:49:37,824 [myid:] - TRACE
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:11221:NIOServerCnxn@378] - Readed from
cleint, size[4] values [java.nio.HeapByteBuffer[pos=4 lim=4 cap=4]]
2012-07-13 01:49:37,825 [myid:] - TRACE
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:11221:NIOServerCnxn@378] - Readed from
cleint, size[45] values [java.nio.HeapByteBuffer[pos=45 lim=45 cap=45]]
2012-07-13 01:49:37,835 [myid:] - TRACE [SyncThread:0:NIOServerCnxn@189] -
Writting to client, size[41] values [[0, 0, 0, 37, 0, 0, 0, 0, 0, 0, 117, 48,
1, 56, 126, -85, -80, -68, 0, 0, 0, 0, 0, 16, -122, 112, 53, -37, -101, 126,
-10, 20, -44, -11, -105, 43, -36, 107, -94, 35, 0]]
2012-07-13 01:49:38,025 [myid:] - TRACE
[main-SendThread(localhost:11221):ClientCnxnSocketNIO@133] - Readed from
server, size[4] values [java.nio.DirectByteBuffer[pos=4 lim=4 cap=4]]
2012-07-13 01:49:38,126 [myid:] - TRACE
[main-SendThread(localhost:11221):ClientCnxnSocketNIO@133] - Readed from
server, size[37] values [java.nio.HeapByteBuffer[pos=37 lim=37 cap=37]]
2012-07-13 01:49:38,233 [myid:] - TRACE
[main-SendThread(localhost:11221):ClientCnxnSocketNIO@111] - Write to server,
size[29] values [[0, 0, 0, 25, 0, 0, 0, 1, 0, 0, 0, 5, 0, 0, 0, 1, 47, 0, 0, 0,
4, 115, 111, 109, 101, -1, -1, -1, -1]]
** Where is the read from the server side?
2012-07-13 01:49:48,336 [myid:] - TRACE
[main-SendThread(localhost:11221):ClientCnxnSocketNIO@111] - Write to server,
size[12] values [[0, 0, 0, 8, -1, -1, -1, -2, 0, 0, 0, 11]]
2012-07-13 01:49:59,667 [myid:] - TRACE
[main-SendThread(localhost:11221):ClientCnxnSocketNIO@111] - Write to server,
size[49] values [[0, 0, 0, 45, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 117,
48, 1, 56, 126, -85, -80, -68, 0, 0, 0, 0, 0, 16, -122, 112, 53, -37, -101,
126, -10, 20, -44, -11, -105, 43, -36, 107, -94, 35, 0]]
2012-07-13 01:49:59,769 [myid:] - TRACE
[main-SendThread(localhost:11221):ClientCnxnSocketNIO@111] - Write to server,
size[12] values [[0, 0, 0, 8, 0, 0, 0, 2, -1, -1, -1, -11]]
2012-07-13 01:49:59,769 [myid:] - TRACE
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:11221:NIOServerCnxn@378] - Readed from
cleint, size[4] values [java.nio.HeapByteBuffer[pos=4 lim=4 cap=4]]
2012-07-13 01:49:59,770 [myid:] - TRACE
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:11221:NIOServerCnxn@378] - Readed from
cleint, size[45] values [java.nio.HeapByteBuffer[pos=45 lim=45 cap=45]]
2012-07-13 01:49:59,770 [myid:] - INFO
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:11221:NIOServerCnxn@1019] - Closed socket
connection for client /127.0.0.1:57448 which had sessionid 0x1387eabb0bc0000
2012-07-13 01:49:59,771 [myid:] - TRACE
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:11221:NIOServerCnxn@189] - Writting to
client, size[41] values [[0, 0, 0, 37, 0, 0, 0, 0, 0, 0, 117, 48, 1, 56, 126,
-85, -80, -68, 0, 0, 0, 0, 0, 16, -122, 112, 53, -37, -101, 126, -10, 20, -44,
-11, -105, 43, -36, 107, -94, 35, 0]]
2012-07-13 01:49:59,872 [myid:] - TRACE
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:11221:NIOServerCnxn@378] - Readed from
cleint, size[4] values [java.nio.HeapByteBuffer[pos=4 lim=4 cap=4]]
2012-07-13 01:49:59,873 [myid:] - TRACE
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:11221:NIOServerCnxn@378] - Readed from
cleint, size[8] values [java.nio.HeapByteBuffer[pos=8 lim=8 cap=8]]
2012-07-13 01:49:59,874 [myid:] - TRACE [SyncThread:0:NIOServerCnxn@189] -
Writting to client, size[20] values [[0, 0, 0, 16, 0, 0, 0, 2, 0, 0, 0, 0, 0,
0, 0, 2, 0, 0, 0, 0]]
2012-07-13 01:49:59,874 [myid:] - TRACE [SyncThread:0:NIOServerCnxn@173] - Add
a buffer to outgoingBuffers, sk sun.nio.ch.SelectionKeyImpl@64aedc96 is valid:
true
2012-07-13 01:49:59,971 [myid:] - TRACE
[main-SendThread(localhost:11221):ClientCnxnSocketNIO@133] - Readed from
server, size[4] values [java.nio.DirectByteBuffer[pos=4 lim=4 cap=4]]
2012-07-13 01:50:00,072 [myid:] - TRACE
[main-SendThread(localhost:11221):ClientCnxnSocketNIO@133] - Readed from
server, size[37] values [java.nio.HeapByteBuffer[pos=37 lim=37 cap=37]]
2012-07-13 01:50:00,174 [myid:] - TRACE
[main-SendThread(localhost:11221):ClientCnxnSocketNIO@133] - Readed from
server, size[4] values [java.nio.DirectByteBuffer[pos=4 lim=4 cap=4]]
2012-07-13 01:50:00,275 [myid:] - TRACE
[main-SendThread(localhost:11221):ClientCnxnSocketNIO@133] - Readed from
server, size[16] values [java.nio.HeapByteBuffer[pos=16 lim=16 cap=16]]
2012-07-13 01:50:00,276 [myid:] - INFO [main:NIOServerCnxn@1019] - Closed
socket connection for client /127.0.0.1:57449 which had sessionid
0x1387eabb0bc0000
{code}
In my search I sow some changes in minor issues in the jdk7 regarding socket
channels, but I don't know if it is the root cause. Tomorrow I will go a little
deeper.
> Test failures with Java 7 on Mac OS X
> -------------------------------------
>
> Key: ZOOKEEPER-1477
> URL: https://issues.apache.org/jira/browse/ZOOKEEPER-1477
> Project: ZooKeeper
> Issue Type: Bug
> Components: server, tests
> Affects Versions: 3.4.3
> Environment: Mac OS X Lion (10.7.4)
> Java version:
> java version "1.7.0_04"
> Java(TM) SE Runtime Environment (build 1.7.0_04-b21)
> Java HotSpot(TM) 64-Bit Server VM (build 23.0-b21, mixed mode)
> Reporter: Diwaker Gupta
> Priority: Critical
>
> I downloaded ZK 3.4.3 sources and ran {{ant test}}. Many of the tests failed,
> including ZooKeeperTest. A common symptom was spurious
> {{ConnectionLossException}}:
> {code}
> 2012-06-01 12:01:23,420 [myid:] - INFO
> [main:JUnit4ZKTestRunner$LoggedInvokeMethod@54] - TEST METHOD FAILED
> testDeleteRecursiveAsync
> org.apache.zookeeper.KeeperException$ConnectionLossException: KeeperErrorCode
> = ConnectionLoss for /
> at
> org.apache.zookeeper.KeeperException.create(KeeperException.java:99)
> at
> org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
> at org.apache.zookeeper.ZooKeeper.setData(ZooKeeper.java:1246)
> at
> org.apache.zookeeper.ZooKeeperTest.testDeleteRecursiveAsync(ZooKeeperTest.java:77)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> ... (snipped)
> {code}
> As background, I was actually investigating some non-deterministic failures
> when using Netflix's Curator with Java 7 (see
> https://github.com/Netflix/curator/issues/79). After a while, I figured I
> should establish a clean ZK baseline first and realized it is actually a ZK
> issue, not a Curator issue.
> We are trying to migrate to Java 7 but this is a blocking issue for us right
> now.
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators:
https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira
