Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Major Major
    • Resolution: Not A Problem
    • Affects Version/s: 3.4.3
    • Fix Version/s: None
    • Component/s: server, tests
    • Labels:
      None
    • 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)

      Description

      I downloaded ZK 3.4.3 sources and ran ant test. Many of the tests failed, including ZooKeeperTest. A common symptom was spurious ConnectionLossException:

      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)
      

      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.

      1. with-ZK-1550.txt
        14 kB
        Diwaker Gupta

        Issue Links

          Activity

          Hide
          Flavio Junqueira added a comment -

          Resolving this issue, since I got no feedback and I'm not observing tests failing in my environment. I have been running often on a mac.

          Show
          Flavio Junqueira added a comment - Resolving this issue, since I got no feedback and I'm not observing tests failing in my environment. I have been running often on a mac.
          Hide
          Flavio Junqueira added a comment -

          I normally don't see an issue. I run regularly on a mac and unit tests run fine. There is no patch attached, btw.

          Show
          Flavio Junqueira added a comment - I normally don't see an issue. I run regularly on a mac and unit tests run fine. There is no patch attached, btw.
          Hide
          Patrick Hunt added a comment -

          Flavio Junqueira are you saying that you tested the attached patch and it resolved the issue for you? Or that you normally don't see an issue and this patch is not needed? (I'm not on a mac so I can't help to test this)

          Show
          Patrick Hunt added a comment - Flavio Junqueira are you saying that you tested the attached patch and it resolved the issue for you? Or that you normally don't see an issue and this patch is not needed? (I'm not on a mac so I can't help to test this)
          Hide
          Flavio Junqueira added a comment -

          I haven't heard anything back, so I'm moving it to 3.5.0. I'm not sure this is still an issue, though, everything seems to work for me on macos.

          Show
          Flavio Junqueira added a comment - I haven't heard anything back, so I'm moving it to 3.5.0. I'm not sure this is still an issue, though, everything seems to work for me on macos.
          Hide
          Flavio Junqueira added a comment -

          Everything seems to work for me: tests pass and I can run both client and server. If there is a fix needed here, I'd like to include it in 3.4.6.

          Show
          Flavio Junqueira added a comment - Everything seems to work for me: tests pass and I can run both client and server. If there is a fix needed here, I'd like to include it in 3.4.6.
          Hide
          Daniel Woo added a comment -

          I have exactly the same issue like Helen's one on Mac OSX 10.8. The client works with both jdk 1.6 and 1.7, but the server only works with 1.6.

          Show
          Daniel Woo added a comment - I have exactly the same issue like Helen's one on Mac OSX 10.8. The client works with both jdk 1.6 and 1.7, but the server only works with 1.6.
          Hide
          Martijn Koster added a comment -

          Some more data points:
          I saw this problem with 3.4.4 on 2nd Oct 2012, on OSX 10.6. I worked around it then by using a nightly build.
          I'm now on OSX 10.8.2, tried 3.4.5, and saw it again. I then upgraded to java jdk 1.7.0_09-b05 (from _04 I believe), and it went away again.

          Show
          Martijn Koster added a comment - Some more data points: I saw this problem with 3.4.4 on 2nd Oct 2012, on OSX 10.6. I worked around it then by using a nightly build. I'm now on OSX 10.8.2, tried 3.4.5, and saw it again. I then upgraded to java jdk 1.7.0_09-b05 (from _04 I believe), and it went away again.
          Hide
          Paulo Ricardo Paz Vital added a comment -

          Patrick, I could build 3.4.5 using IBM Java 7 SR 3 and it's working with no problems (the environment is a x86_64 running RHEL6.3).

          First, I tried to build 3.4.4 with IBM Java 7 SR 3, and got the same problems as reported by Diwaker Gupta in the beginning of this thread. After checked the comments from Eugene Koontz regarding the ZOOKEEPER-1550, and the good results reported by Diwaker after applied the patch on 3.4.3, I decided to check the current version (3.4.5) and trunk.

          Both versions (3.4.5 and trunk) are build with no problems with IBM (7 SR 3) and Oracle (7 update 9) JVMs.

          Show
          Paulo Ricardo Paz Vital added a comment - Patrick, I could build 3.4.5 using IBM Java 7 SR 3 and it's working with no problems (the environment is a x86_64 running RHEL6.3). First, I tried to build 3.4.4 with IBM Java 7 SR 3, and got the same problems as reported by Diwaker Gupta in the beginning of this thread. After checked the comments from Eugene Koontz regarding the ZOOKEEPER-1550 , and the good results reported by Diwaker after applied the patch on 3.4.3, I decided to check the current version (3.4.5) and trunk. Both versions (3.4.5 and trunk) are build with no problems with IBM (7 SR 3) and Oracle (7 update 9) JVMs.
          Hide
          Patrick Hunt added a comment -

          Has anyone tried against 3.4.5? Do we have any insight whether this was also happening with the 3.3 branch?

          Show
          Patrick Hunt added a comment - Has anyone tried against 3.4.5? Do we have any insight whether this was also happening with the 3.3 branch?
          Hide
          Roman Shaposhnik added a comment -

          Fedora 18 is not officially released yet, but over at Bigtop (http://bigtop.apache.org) we run regular tests with the OS supplied JDK and things have been really great on the following set of platforms: http://bigtop01.cloudera.org:8080/view/Bigtop-trunk/job/Bigtop-trunk-packagetest/

          FWIW: I believe that Fedora 17 comes with exactly the same version of JDK 1.7.0_09-icedtea.

          Show
          Roman Shaposhnik added a comment - Fedora 18 is not officially released yet, but over at Bigtop ( http://bigtop.apache.org ) we run regular tests with the OS supplied JDK and things have been really great on the following set of platforms: http://bigtop01.cloudera.org:8080/view/Bigtop-trunk/job/Bigtop-trunk-packagetest/ FWIW: I believe that Fedora 17 comes with exactly the same version of JDK 1.7.0_09-icedtea.
          Hide
          Raul Gutierrez Segales added a comment -

          (On 3.4.4)

          Show
          Raul Gutierrez Segales added a comment - (On 3.4.4)
          Hide
          Raul Gutierrez Segales added a comment -

          FWIW I have the same issue with zkCli on Fedora 18 / JDK 1.7.0_09-icedtea.

          Show
          Raul Gutierrez Segales added a comment - FWIW I have the same issue with zkCli on Fedora 18 / JDK 1.7.0_09-icedtea.
          Hide
          Dan Ertman added a comment -

          Second Helen's comments above - zkCli from Zookeeper 3.4.4 fails on Mac JDK 1.7.0_09 when you try to ls /. I tried -Djava.nio.channels.spi.SelectorProvider=sun.nio.ch.KQueueSelectorProvider on both client and server, no effect.

          Show
          Dan Ertman added a comment - Second Helen's comments above - zkCli from Zookeeper 3.4.4 fails on Mac JDK 1.7.0_09 when you try to ls /. I tried -Djava.nio.channels.spi.SelectorProvider=sun.nio.ch.KQueueSelectorProvider on both client and server, no effect.
          Hide
          Helen Williamson added a comment -

          I'm also experiencing a similar problem using the zkCli shell script. I've started up 5 zookeeper servers using QuorumPeerMain from the zookeeper jar.

          With Java 1.6.0_37 I get the following output:

          MC00635:bin helen.williamson$ ./zkCli.sh
          Connecting to localhost:2181
          2012-11-05 10:50:35,648 [myid:] - INFO  [main:Environment@100] - Client environment:zookeeper.version=3.4.4-1386507, built on 09/17/2012 08:33 GMT
          2012-11-05 10:50:35,651 [myid:] - INFO  [main:Environment@100] - Client environment:host.name=dhcp-192-168-101-135.tea.mindcandy.com
          2012-11-05 10:50:35,651 [myid:] - INFO  [main:Environment@100] - Client environment:java.version=1.6.0_37
          2012-11-05 10:50:35,651 [myid:] - INFO  [main:Environment@100] - Client environment:java.vendor=Apple Inc.
          2012-11-05 10:50:35,652 [myid:] - INFO  [main:Environment@100] - Client environment:java.home=/System/Library/Java/JavaVirtualMachines/1.6.0.jdk/Contents/Home
          2012-11-05 10:50:35,652 [myid:] - INFO  [main:Environment@100] - Client environment:java.class.path=/Users/helen.williamson/workspace/bartender/target/zookeeper/bin/../build/classes:/Users/helen.williamson/workspace/bartender/target/zookeeper/bin/../build/lib/*.jar:/Users/helen.williamson/workspace/bartender/target/zookeeper/bin/../lib/slf4j-log4j12-1.6.1.jar:/Users/helen.williamson/workspace/bartender/target/zookeeper/bin/../lib/slf4j-api-1.6.1.jar:/Users/helen.williamson/workspace/bartender/target/zookeeper/bin/../lib/netty-3.2.2.Final.jar:/Users/helen.williamson/workspace/bartender/target/zookeeper/bin/../lib/log4j-1.2.15.jar:/Users/helen.williamson/workspace/bartender/target/zookeeper/bin/../lib/jline-0.9.94.jar:/Users/helen.williamson/workspace/bartender/target/zookeeper/bin/../zookeeper-3.4.4.jar:/Users/helen.williamson/workspace/bartender/target/zookeeper/bin/../src/java/lib/*.jar:/Users/helen.williamson/workspace/bartender/target/zookeeper/bin/../conf:
          2012-11-05 10:50:35,652 [myid:] - INFO  [main:Environment@100] - Client environment:java.library.path=.:/Library/Java/Extensions:/System/Library/Java/Extensions:/usr/lib/java
          2012-11-05 10:50:35,653 [myid:] - INFO  [main:Environment@100] - Client environment:java.io.tmpdir=/var/folders/4l/yzr37v6s3zz8hfsggnjmzbg00000gp/T/
          2012-11-05 10:50:35,653 [myid:] - INFO  [main:Environment@100] - Client environment:java.compiler=<NA>
          2012-11-05 10:50:35,653 [myid:] - INFO  [main:Environment@100] - Client environment:os.name=Mac OS X
          2012-11-05 10:50:35,654 [myid:] - INFO  [main:Environment@100] - Client environment:os.arch=x86_64
          2012-11-05 10:50:35,654 [myid:] - INFO  [main:Environment@100] - Client environment:os.version=10.7.5
          2012-11-05 10:50:35,654 [myid:] - INFO  [main:Environment@100] - Client environment:user.name=helen.williamson
          2012-11-05 10:50:35,655 [myid:] - INFO  [main:Environment@100] - Client environment:user.home=/Users/helen.williamson
          2012-11-05 10:50:35,655 [myid:] - INFO  [main:Environment@100] - Client environment:user.dir=/Users/helen.williamson/workspace/bartender/target/zookeeper-3.4.4/bin
          2012-11-05 10:50:35,656 [myid:] - INFO  [main:ZooKeeper@433] - Initiating client connection, connectString=localhost:2181 sessionTimeout=30000 watcher=org.apache.zookeeper.ZooKeeperMain$MyWatcher@6b4da8f4
          Welcome to ZooKeeper!
          2012-11-05 10:50:35,687 [myid:] - INFO  [main-SendThread(localhost:2181):ClientCnxn$SendThread@966] - Opening socket connection to server localhost/127.0.0.1:2181. Will not attempt to authenticate using SASL (Unable to locate a login configuration)
          JLine support is enabled
          2012-11-05 10:50:35,694 [myid:] - INFO  [main-SendThread(localhost:2181):ClientCnxn$SendThread@849] - Socket connection established to localhost/127.0.0.1:2181, initiating session
          2012-11-05 10:50:35,715 [myid:] - INFO  [main-SendThread(localhost:2181):ClientCnxn$SendThread@1207] - Session establishment complete on server localhost/127.0.0.1:2181, sessionid = 0x13ad009f0770002, negotiated timeout = 30000
          
          WATCHER::
          
          WatchedEvent state:SyncConnected type:None path:null
          [zk: localhost:2181(CONNECTED) 0] ls /
          [zookeeper]
          

          With Java 1.7.0_09 I get:

          MC00635:bin helen.williamson$ ./zkCli.sh
          Connecting to localhost:2181
          2012-11-05 10:45:44,634 [myid:] - INFO  [main:Environment@100] - Client environment:zookeeper.version=3.4.4-1386507, built on 09/17/2012 08:33 GMT
          2012-11-05 10:45:44,674 [myid:] - INFO  [main:Environment@100] - Client environment:host.name=<NA>
          2012-11-05 10:45:44,674 [myid:] - INFO  [main:Environment@100] - Client environment:java.version=1.7.0_09
          2012-11-05 10:45:44,675 [myid:] - INFO  [main:Environment@100] - Client environment:java.vendor=Oracle Corporation
          2012-11-05 10:45:44,676 [myid:] - INFO  [main:Environment@100] - Client environment:java.home=/Library/Java/JavaVirtualMachines/jdk1.7.0_09.jdk/Contents/Home/jre
          2012-11-05 10:45:44,677 [myid:] - INFO  [main:Environment@100] - Client environment:java.class.path=/Users/helen.williamson/workspace/bartender/target/zookeeper/bin/../build/classes:/Users/helen.williamson/workspace/bartender/target/zookeeper/bin/../build/lib/*.jar:/Users/helen.williamson/workspace/bartender/target/zookeeper/bin/../lib/slf4j-log4j12-1.6.1.jar:/Users/helen.williamson/workspace/bartender/target/zookeeper/bin/../lib/slf4j-api-1.6.1.jar:/Users/helen.williamson/workspace/bartender/target/zookeeper/bin/../lib/netty-3.2.2.Final.jar:/Users/helen.williamson/workspace/bartender/target/zookeeper/bin/../lib/log4j-1.2.15.jar:/Users/helen.williamson/workspace/bartender/target/zookeeper/bin/../lib/jline-0.9.94.jar:/Users/helen.williamson/workspace/bartender/target/zookeeper/bin/../zookeeper-3.4.4.jar:/Users/helen.williamson/workspace/bartender/target/zookeeper/bin/../src/java/lib/*.jar:/Users/helen.williamson/workspace/bartender/target/zookeeper/bin/../conf:
          2012-11-05 10:45:44,678 [myid:] - INFO  [main:Environment@100] - Client environment:java.library.path=/Users/helen.williamson/Library/Java/Extensions:/Library/Java/Extensions:/Network/Library/Java/Extensions:/System/Library/Java/Extensions:/usr/lib/java:.
          2012-11-05 10:45:44,678 [myid:] - INFO  [main:Environment@100] - Client environment:java.io.tmpdir=/var/folders/4l/yzr37v6s3zz8hfsggnjmzbg00000gp/T/
          2012-11-05 10:45:44,679 [myid:] - INFO  [main:Environment@100] - Client environment:java.compiler=<NA>
          2012-11-05 10:45:44,679 [myid:] - INFO  [main:Environment@100] - Client environment:os.name=Mac OS X
          2012-11-05 10:45:44,680 [myid:] - INFO  [main:Environment@100] - Client environment:os.arch=x86_64
          2012-11-05 10:45:44,680 [myid:] - INFO  [main:Environment@100] - Client environment:os.version=10.7.5
          2012-11-05 10:45:44,681 [myid:] - INFO  [main:Environment@100] - Client environment:user.name=helen.williamson
          2012-11-05 10:45:44,682 [myid:] - INFO  [main:Environment@100] - Client environment:user.home=/Users/helen.williamson
          2012-11-05 10:45:44,682 [myid:] - INFO  [main:Environment@100] - Client environment:user.dir=/Users/helen.williamson/workspace/bartender/target/zookeeper-3.4.4/bin
          2012-11-05 10:45:44,684 [myid:] - INFO  [main:ZooKeeper@433] - Initiating client connection, connectString=localhost:2181 sessionTimeout=30000 watcher=org.apache.zookeeper.ZooKeeperMain$MyWatcher@6ad5d980
          Welcome to ZooKeeper!
          2012-11-05 10:45:44,863 [myid:] - INFO  [main-SendThread(localhost:2181):ClientCnxn$SendThread@966] - Opening socket connection to server localhost/127.0.0.1:2181. Will not attempt to authenticate using SASL (unknown error)
          JLine support is enabled
          2012-11-05 10:45:44,973 [myid:] - INFO  [main-SendThread(localhost:2181):ClientCnxn$SendThread@849] - Socket connection established to localhost/127.0.0.1:2181, initiating session
          2012-11-05 10:45:45,011 [myid:] - INFO  [main-SendThread(localhost:2181):ClientCnxn$SendThread@1207] - Session establishment complete on server localhost/127.0.0.1:2181, sessionid = 0x13ad009f0770001, negotiated timeout = 30000
          
          WATCHER::
          
          WatchedEvent state:SyncConnected type:None path:null
          [zk: localhost:2181(CONNECTED) 0] 
          [zk: localhost:2181(CONNECTED) 0] ls /
          2012-11-05 10:46:05,004 [myid:] - INFO  [main-SendThread(localhost:2181):ClientCnxn$SendThread@1083] - Client session timed out, have not heard from server in 20001ms for sessionid 0x13ad009f0770001, closing socket connection and attempting reconnect
          
          WATCHER::
          
          WatchedEvent state:Disconnected type:None path:null
          Exception in thread "main" 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.getChildren(ZooKeeper.java:1463)
          	at org.apache.zookeeper.ZooKeeper.getChildren(ZooKeeper.java:1491)
          	at org.apache.zookeeper.ZooKeeperMain.processZKCmd(ZooKeeperMain.java:725)
          	at org.apache.zookeeper.ZooKeeperMain.processCmd(ZooKeeperMain.java:593)
          	at org.apache.zookeeper.ZooKeeperMain.executeLine(ZooKeeperMain.java:365)
          	at org.apache.zookeeper.ZooKeeperMain.run(ZooKeeperMain.java:323)
          	at org.apache.zookeeper.ZooKeeperMain.main(ZooKeeperMain.java:282)
          

          This can be reproduced by switching JAVA_HOME between 1.6 and 1.7.

          Show
          Helen Williamson added a comment - I'm also experiencing a similar problem using the zkCli shell script. I've started up 5 zookeeper servers using QuorumPeerMain from the zookeeper jar. With Java 1.6.0_37 I get the following output: MC00635:bin helen.williamson$ ./zkCli.sh Connecting to localhost:2181 2012-11-05 10:50:35,648 [myid:] - INFO [main:Environment@100] - Client environment:zookeeper.version=3.4.4-1386507, built on 09/17/2012 08:33 GMT 2012-11-05 10:50:35,651 [myid:] - INFO [main:Environment@100] - Client environment:host.name=dhcp-192-168-101-135.tea.mindcandy.com 2012-11-05 10:50:35,651 [myid:] - INFO [main:Environment@100] - Client environment:java.version=1.6.0_37 2012-11-05 10:50:35,651 [myid:] - INFO [main:Environment@100] - Client environment:java.vendor=Apple Inc. 2012-11-05 10:50:35,652 [myid:] - INFO [main:Environment@100] - Client environment:java.home=/ System /Library/Java/JavaVirtualMachines/1.6.0.jdk/Contents/Home 2012-11-05 10:50:35,652 [myid:] - INFO [main:Environment@100] - Client environment:java.class.path=/Users/helen.williamson/workspace/bartender/target/zookeeper/bin/../build/classes:/Users/helen.williamson/workspace/bartender/target/zookeeper/bin/../build/lib/*.jar:/Users/helen.williamson/workspace/bartender/target/zookeeper/bin/../lib/slf4j-log4j12-1.6.1.jar:/Users/helen.williamson/workspace/bartender/target/zookeeper/bin/../lib/slf4j-api-1.6.1.jar:/Users/helen.williamson/workspace/bartender/target/zookeeper/bin/../lib/netty-3.2.2.Final.jar:/Users/helen.williamson/workspace/bartender/target/zookeeper/bin/../lib/log4j-1.2.15.jar:/Users/helen.williamson/workspace/bartender/target/zookeeper/bin/../lib/jline-0.9.94.jar:/Users/helen.williamson/workspace/bartender/target/zookeeper/bin/../zookeeper-3.4.4.jar:/Users/helen.williamson/workspace/bartender/target/zookeeper/bin/../src/java/lib/*.jar:/Users/helen.williamson/workspace/bartender/target/zookeeper/bin/../conf: 2012-11-05 10:50:35,652 [myid:] - INFO [main:Environment@100] - Client environment:java.library.path=.:/Library/Java/Extensions:/ System /Library/Java/Extensions:/usr/lib/java 2012-11-05 10:50:35,653 [myid:] - INFO [main:Environment@100] - Client environment:java.io.tmpdir=/ var /folders/4l/yzr37v6s3zz8hfsggnjmzbg00000gp/T/ 2012-11-05 10:50:35,653 [myid:] - INFO [main:Environment@100] - Client environment:java.compiler=<NA> 2012-11-05 10:50:35,653 [myid:] - INFO [main:Environment@100] - Client environment:os.name=Mac OS X 2012-11-05 10:50:35,654 [myid:] - INFO [main:Environment@100] - Client environment:os.arch=x86_64 2012-11-05 10:50:35,654 [myid:] - INFO [main:Environment@100] - Client environment:os.version=10.7.5 2012-11-05 10:50:35,654 [myid:] - INFO [main:Environment@100] - Client environment:user.name=helen.williamson 2012-11-05 10:50:35,655 [myid:] - INFO [main:Environment@100] - Client environment:user.home=/Users/helen.williamson 2012-11-05 10:50:35,655 [myid:] - INFO [main:Environment@100] - Client environment:user.dir=/Users/helen.williamson/workspace/bartender/target/zookeeper-3.4.4/bin 2012-11-05 10:50:35,656 [myid:] - INFO [main:ZooKeeper@433] - Initiating client connection, connectString=localhost:2181 sessionTimeout=30000 watcher=org.apache.zookeeper.ZooKeeperMain$MyWatcher@6b4da8f4 Welcome to ZooKeeper! 2012-11-05 10:50:35,687 [myid:] - INFO [main-SendThread(localhost:2181):ClientCnxn$SendThread@966] - Opening socket connection to server localhost/127.0.0.1:2181. Will not attempt to authenticate using SASL (Unable to locate a login configuration) JLine support is enabled 2012-11-05 10:50:35,694 [myid:] - INFO [main-SendThread(localhost:2181):ClientCnxn$SendThread@849] - Socket connection established to localhost/127.0.0.1:2181, initiating session 2012-11-05 10:50:35,715 [myid:] - INFO [main-SendThread(localhost:2181):ClientCnxn$SendThread@1207] - Session establishment complete on server localhost/127.0.0.1:2181, sessionid = 0x13ad009f0770002, negotiated timeout = 30000 WATCHER:: WatchedEvent state:SyncConnected type:None path: null [zk: localhost:2181(CONNECTED) 0] ls / [zookeeper] With Java 1.7.0_09 I get: MC00635:bin helen.williamson$ ./zkCli.sh Connecting to localhost:2181 2012-11-05 10:45:44,634 [myid:] - INFO [main:Environment@100] - Client environment:zookeeper.version=3.4.4-1386507, built on 09/17/2012 08:33 GMT 2012-11-05 10:45:44,674 [myid:] - INFO [main:Environment@100] - Client environment:host.name=<NA> 2012-11-05 10:45:44,674 [myid:] - INFO [main:Environment@100] - Client environment:java.version=1.7.0_09 2012-11-05 10:45:44,675 [myid:] - INFO [main:Environment@100] - Client environment:java.vendor=Oracle Corporation 2012-11-05 10:45:44,676 [myid:] - INFO [main:Environment@100] - Client environment:java.home=/Library/Java/JavaVirtualMachines/jdk1.7.0_09.jdk/Contents/Home/jre 2012-11-05 10:45:44,677 [myid:] - INFO [main:Environment@100] - Client environment:java.class.path=/Users/helen.williamson/workspace/bartender/target/zookeeper/bin/../build/classes:/Users/helen.williamson/workspace/bartender/target/zookeeper/bin/../build/lib/*.jar:/Users/helen.williamson/workspace/bartender/target/zookeeper/bin/../lib/slf4j-log4j12-1.6.1.jar:/Users/helen.williamson/workspace/bartender/target/zookeeper/bin/../lib/slf4j-api-1.6.1.jar:/Users/helen.williamson/workspace/bartender/target/zookeeper/bin/../lib/netty-3.2.2.Final.jar:/Users/helen.williamson/workspace/bartender/target/zookeeper/bin/../lib/log4j-1.2.15.jar:/Users/helen.williamson/workspace/bartender/target/zookeeper/bin/../lib/jline-0.9.94.jar:/Users/helen.williamson/workspace/bartender/target/zookeeper/bin/../zookeeper-3.4.4.jar:/Users/helen.williamson/workspace/bartender/target/zookeeper/bin/../src/java/lib/*.jar:/Users/helen.williamson/workspace/bartender/target/zookeeper/bin/../conf: 2012-11-05 10:45:44,678 [myid:] - INFO [main:Environment@100] - Client environment:java.library.path=/Users/helen.williamson/Library/Java/Extensions:/Library/Java/Extensions:/Network/Library/Java/Extensions:/ System /Library/Java/Extensions:/usr/lib/java:. 2012-11-05 10:45:44,678 [myid:] - INFO [main:Environment@100] - Client environment:java.io.tmpdir=/ var /folders/4l/yzr37v6s3zz8hfsggnjmzbg00000gp/T/ 2012-11-05 10:45:44,679 [myid:] - INFO [main:Environment@100] - Client environment:java.compiler=<NA> 2012-11-05 10:45:44,679 [myid:] - INFO [main:Environment@100] - Client environment:os.name=Mac OS X 2012-11-05 10:45:44,680 [myid:] - INFO [main:Environment@100] - Client environment:os.arch=x86_64 2012-11-05 10:45:44,680 [myid:] - INFO [main:Environment@100] - Client environment:os.version=10.7.5 2012-11-05 10:45:44,681 [myid:] - INFO [main:Environment@100] - Client environment:user.name=helen.williamson 2012-11-05 10:45:44,682 [myid:] - INFO [main:Environment@100] - Client environment:user.home=/Users/helen.williamson 2012-11-05 10:45:44,682 [myid:] - INFO [main:Environment@100] - Client environment:user.dir=/Users/helen.williamson/workspace/bartender/target/zookeeper-3.4.4/bin 2012-11-05 10:45:44,684 [myid:] - INFO [main:ZooKeeper@433] - Initiating client connection, connectString=localhost:2181 sessionTimeout=30000 watcher=org.apache.zookeeper.ZooKeeperMain$MyWatcher@6ad5d980 Welcome to ZooKeeper! 2012-11-05 10:45:44,863 [myid:] - INFO [main-SendThread(localhost:2181):ClientCnxn$SendThread@966] - Opening socket connection to server localhost/127.0.0.1:2181. Will not attempt to authenticate using SASL (unknown error) JLine support is enabled 2012-11-05 10:45:44,973 [myid:] - INFO [main-SendThread(localhost:2181):ClientCnxn$SendThread@849] - Socket connection established to localhost/127.0.0.1:2181, initiating session 2012-11-05 10:45:45,011 [myid:] - INFO [main-SendThread(localhost:2181):ClientCnxn$SendThread@1207] - Session establishment complete on server localhost/127.0.0.1:2181, sessionid = 0x13ad009f0770001, negotiated timeout = 30000 WATCHER:: WatchedEvent state:SyncConnected type:None path: null [zk: localhost:2181(CONNECTED) 0] [zk: localhost:2181(CONNECTED) 0] ls / 2012-11-05 10:46:05,004 [myid:] - INFO [main-SendThread(localhost:2181):ClientCnxn$SendThread@1083] - Client session timed out, have not heard from server in 20001ms for sessionid 0x13ad009f0770001, closing socket connection and attempting reconnect WATCHER:: WatchedEvent state:Disconnected type:None path: null Exception in thread "main" 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.getChildren(ZooKeeper.java:1463) at org.apache.zookeeper.ZooKeeper.getChildren(ZooKeeper.java:1491) at org.apache.zookeeper.ZooKeeperMain.processZKCmd(ZooKeeperMain.java:725) at org.apache.zookeeper.ZooKeeperMain.processCmd(ZooKeeperMain.java:593) at org.apache.zookeeper.ZooKeeperMain.executeLine(ZooKeeperMain.java:365) at org.apache.zookeeper.ZooKeeperMain.run(ZooKeeperMain.java:323) at org.apache.zookeeper.ZooKeeperMain.main(ZooKeeperMain.java:282) This can be reproduced by switching JAVA_HOME between 1.6 and 1.7.
          Hide
          Mårten Gustafson added a comment -

          Again FWIW in this context: problem vanished when upgrading to JDK 1.7.0_07, ie the storm-starter scenario, and it's embedded ZooKeeper, runs fine.

          Show
          Mårten Gustafson added a comment - Again FWIW in this context: problem vanished when upgrading to JDK 1.7.0_07 , ie the storm-starter scenario, and it's embedded ZooKeeper, runs fine.
          Hide
          Eugene Koontz added a comment -

          Thanks Martin, Good to know that multiple Java versions in OS X works.

          Show
          Eugene Koontz added a comment - Thanks Martin, Good to know that multiple Java versions in OS X works.
          Hide
          Mårten Gustafson added a comment -

          FWIW:

          I ended up here trying to debug problems with running a local Storm cluster (which uses an embedded ZooKeeper) and followed the Curator errors and related bug reports to this issue.

          I just did somewhat of a bare minimum test case using the storm-starter project on OS X 10.8.2 using Java 1.7.0_05 and then switching to Java 1.6.0_35 (so yes, Eugene Koontz you can switch back and forth using the "Java Prefernces" app in OS X).

          With Java 1.6.0_35 the storm-starter runs flawlessly whereas on 1.7.0_05 it's stuck trying to connect to ZooKeeper. ZooKeeper version is 3.4.4.

          I started trying to hack a build of Curator together with ZK 3.5 from source but have to cave and wrap this day up. If I manage to get a test run with 3.5 I'll update here.

          Show
          Mårten Gustafson added a comment - FWIW: I ended up here trying to debug problems with running a local Storm cluster (which uses an embedded ZooKeeper) and followed the Curator errors and related bug reports to this issue. I just did somewhat of a bare minimum test case using the storm-starter project on OS X 10.8.2 using Java 1.7.0_05 and then switching to Java 1.6.0_35 (so yes, Eugene Koontz you can switch back and forth using the "Java Prefernces" app in OS X). With Java 1.6.0_35 the storm-starter runs flawlessly whereas on 1.7.0_05 it's stuck trying to connect to ZooKeeper. ZooKeeper version is 3.4.4 . I started trying to hack a build of Curator together with ZK 3.5 from source but have to cave and wrap this day up. If I manage to get a test run with 3.5 I'll update here.
          Hide
          Mahadev konar added a comment -

          Downgrading to Major given the recent updates on this jira.

          Show
          Mahadev konar added a comment - Downgrading to Major given the recent updates on this jira.
          Hide
          Mahadev konar added a comment -

          Thats fine Diwaker. Ill downgrade this jira to a major and mark it for the next release. We can just ship 3.4.5 with fix for ZOOKEEPER-1550.

          Itll be good to upload the tests logs for those that fail but its not urgent. We can do it later for 3.4.6.

          Thanks.

          Show
          Mahadev konar added a comment - Thats fine Diwaker. Ill downgrade this jira to a major and mark it for the next release. We can just ship 3.4.5 with fix for ZOOKEEPER-1550 . Itll be good to upload the tests logs for those that fail but its not urgent. We can do it later for 3.4.6. Thanks.
          Hide
          Diwaker Gupta added a comment -

          Arghh! I accidentally deleted all the logs from the run with the patch :-/ I can rerun if that'll help.

          Show
          Diwaker Gupta added a comment - Arghh! I accidentally deleted all the logs from the run with the patch :-/ I can rerun if that'll help.
          Hide
          Diwaker Gupta added a comment -

          Eugene Koontz Good prediction – your patch significantly improved things for me!

          Mahadev konar Even with Eugene's patch, some tests failed for me. I'm attaching summary as well as the logs. I also ran tests without his patch but they're still not done (45 min and counting) and many many of them have already failed (many of which passed with Eugene's patch). In summary, +2 for the patch! But we should still investigate the remaining failures.

          Show
          Diwaker Gupta added a comment - Eugene Koontz Good prediction – your patch significantly improved things for me! Mahadev konar Even with Eugene's patch, some tests failed for me. I'm attaching summary as well as the logs. I also ran tests without his patch but they're still not done (45 min and counting) and many many of them have already failed (many of which passed with Eugene's patch). In summary, +2 for the patch! But we should still investigate the remaining failures.
          Hide
          Mahadev konar added a comment -

          Diwaker,
          The usual time on a linux box is around 40 mins or so.

          Show
          Mahadev konar added a comment - Diwaker, The usual time on a linux box is around 40 mins or so.
          Hide
          Eugene Koontz added a comment -

          Thanks Diwaker, I predict you will get fewer errors, at least, if not zero

          May I ask, are you able to install JDK7 on Mac OS X and still be able to select JDK and JVM 6? I'd like to try to install JDK 7 but only if I can still select JDK/JVM 6 for testing.

          Show
          Eugene Koontz added a comment - Thanks Diwaker, I predict you will get fewer errors, at least, if not zero May I ask, are you able to install JDK7 on Mac OS X and still be able to select JDK and JVM 6? I'd like to try to install JDK 7 but only if I can still select JDK/JVM 6 for testing.
          Hide
          Diwaker Gupta added a comment -

          Will do. How long should the tests be expected to run for? The last time I ran ZK tests (few days ago), they didn't run to completion even after 30 minutes, at which point I killed the run.

          Show
          Diwaker Gupta added a comment - Will do. How long should the tests be expected to run for? The last time I ran ZK tests (few days ago), they didn't run to completion even after 30 minutes, at which point I killed the run.
          Hide
          Mahadev konar added a comment -

          Thanks Diwaker. Could you please upload a summary of the tests failing and the logs as well?

          Show
          Mahadev konar added a comment - Thanks Diwaker. Could you please upload a summary of the tests failing and the logs as well?
          Hide
          Diwaker Gupta added a comment -

          Mahadev konar Happy to test though I'm pretty sure this is unrelated to ZOOKEEPER-1550 – recall that I'm using Oracle JDK (not OpenJDK) and I'm on Mac. I haven't been able to ever successfully run ZK tests on a Mac with JDK7 (starting with 7u3, now on 7u7). Things were broken with ZK 3.4.3 and have just become worse with 3.4.4. Will report back shortly with the patch in 1550.

          Show
          Diwaker Gupta added a comment - Mahadev konar Happy to test though I'm pretty sure this is unrelated to ZOOKEEPER-1550 – recall that I'm using Oracle JDK (not OpenJDK) and I'm on Mac. I haven't been able to ever successfully run ZK tests on a Mac with JDK7 (starting with 7u3, now on 7u7). Things were broken with ZK 3.4.3 and have just become worse with 3.4.4. Will report back shortly with the patch in 1550.
          Hide
          Mahadev konar added a comment -

          Diwaker,
          Would you be able to run the tests along with Eugenes patch on ZOOKEEPER-1550 ? If not please let me know. I can go ahead and run it.

          Show
          Mahadev konar added a comment - Diwaker, Would you be able to run the tests along with Eugenes patch on ZOOKEEPER-1550 ? If not please let me know. I can go ahead and run it.
          Hide
          Eugene Koontz added a comment -

          (the above warnings do not appear with Oracle Java 6's javac).

          Show
          Eugene Koontz added a comment - (the above warnings do not appear with Oracle Java 6's javac).
          Hide
          Eugene Koontz added a comment -

          I noted this in javac's output when using Oracle Java 7 on Linux:

          compile:
              [javac] Compiling 164 source files to /home/ec2-user/zookeeper/build/classes
              [javac] warning: [options] bootstrap class path not set in conjunction with -source 1.5
              [javac] /home/ec2-user/zookeeper/src/java/main/org/apache/zookeeper/jmx/ManagedUtil.java:62: warning: [rawtypes] found raw type: Enumeration
              [javac]         Enumeration enumer = r.getCurrentLoggers();
              [javac]         ^
              [javac]   missing type arguments for generic class Enumeration<E>
              [javac]   where E is a type-variable:
              [javac]     E extends Object declared in interface Enumeration
              [javac] /home/ec2-user/zookeeper/src/java/main/org/apache/zookeeper/server/util/KerberosUtil.java:39: warning: [rawtypes] found raw type: Class
              [javac]     getInstanceMethod = classRef.getMethod("getInstance", new Class[0]);
              [javac]                                                               ^
              [javac]   missing type arguments for generic class Class<T>
              [javac]   where T is a type-variable:
              [javac]     T extends Object declared in class Class
              [javac] /home/ec2-user/zookeeper/src/java/main/org/apache/zookeeper/server/util/KerberosUtil.java:42: warning: [rawtypes] found raw type: Class
              [javac]          new Class[0]);
              [javac]              ^
              [javac]   missing type arguments for generic class Class<T>
              [javac]   where T is a type-variable:
              [javac]     T extends Object declared in class Class
              [javac] 4 warnings
          
          Show
          Eugene Koontz added a comment - I noted this in javac's output when using Oracle Java 7 on Linux: compile: [javac] Compiling 164 source files to /home/ec2-user/zookeeper/build/classes [javac] warning: [options] bootstrap class path not set in conjunction with -source 1.5 [javac] /home/ec2-user/zookeeper/src/java/main/org/apache/zookeeper/jmx/ManagedUtil.java:62: warning: [rawtypes] found raw type: Enumeration [javac] Enumeration enumer = r.getCurrentLoggers(); [javac] ^ [javac] missing type arguments for generic class Enumeration<E> [javac] where E is a type-variable: [javac] E extends Object declared in interface Enumeration [javac] /home/ec2-user/zookeeper/src/java/main/org/apache/zookeeper/server/util/KerberosUtil.java:39: warning: [rawtypes] found raw type: Class [javac] getInstanceMethod = classRef.getMethod( "getInstance" , new Class [0]); [javac] ^ [javac] missing type arguments for generic class Class <T> [javac] where T is a type-variable: [javac] T extends Object declared in class Class [javac] /home/ec2-user/zookeeper/src/java/main/org/apache/zookeeper/server/util/KerberosUtil.java:42: warning: [rawtypes] found raw type: Class [javac] new Class [0]); [javac] ^ [javac] missing type arguments for generic class Class <T> [javac] where T is a type-variable: [javac] T extends Object declared in class Class [javac] 4 warnings
          Hide
          Eugene Koontz added a comment -

          Sorry, meant "lets 'ant clean test' pass with Oracle Java 7 on Linux"

          Show
          Eugene Koontz added a comment - Sorry, meant "lets 'ant clean test' pass with Oracle Java 7 on Linux"
          Hide
          Eugene Koontz added a comment -

          Patch with ZOOKEEPER-1550 lets Java 7 on Linux. Have not tested with Mac OS X yet.

          Show
          Eugene Koontz added a comment - Patch with ZOOKEEPER-1550 lets Java 7 on Linux. Have not tested with Mac OS X yet.
          Hide
          Diwaker Gupta added a comment -

          Update:

          • With JDK 7u7 on Mac and ZK 3.4.3, I don't see the ConnectionLoss exceptions anymore (rather I haven't yet observed them)
          • With JDK 7u7 on Mac and ZK 3.4.4, I see even more ConnectionLoss exceptions than before :-/
          Show
          Diwaker Gupta added a comment - Update: With JDK 7u7 on Mac and ZK 3.4.3, I don't see the ConnectionLoss exceptions anymore (rather I haven't yet observed them) With JDK 7u7 on Mac and ZK 3.4.4, I see even more ConnectionLoss exceptions than before :-/
          Hide
          Diego Oliveira added a comment -

          It is a bug in the JDK7 macosx system call as described here http://www.oracle.com/technetwork/java/javase/7u4-relnotes-1575007.html as the bug says there is a workaround, add this to your test -Djava.nio.channels.spi.SelectorProvider=sun.nio.ch.KQueueSelectorProvider.

          All my tests passed for org.apache.zookeeper.ZooKeeperTest. Others are broken, I found that the log output is used as part of tests results and I change the root log level to find the communication problem, so some tests failed. I'm fixing the test to be a little less dependent of the system log level configuration, enforcing his own.

          Show
          Diego Oliveira added a comment - It is a bug in the JDK7 macosx system call as described here http://www.oracle.com/technetwork/java/javase/7u4-relnotes-1575007.html as the bug says there is a workaround, add this to your test -Djava.nio.channels.spi.SelectorProvider=sun.nio.ch.KQueueSelectorProvider. All my tests passed for org.apache.zookeeper.ZooKeeperTest . Others are broken, I found that the log output is used as part of tests results and I change the root log level to find the communication problem, so some tests failed. I'm fixing the test to be a little less dependent of the system log level configuration, enforcing his own.
          Hide
          Diego Oliveira added a comment -

          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:

          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]]
          

          Jdk7 log.

          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
          
          

          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.

          Show
          Diego Oliveira added a comment - 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: 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]] Jdk7 log. 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 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.
          Hide
          Diego Oliveira added a comment -

          I did some testing and it appears to be something time related. Running a test in debug mode (ZooKeeperTest.testDeleteRecursive) sometimes works. Going a little deeper it looks like the channel is going in a broken state and the client can not send the next package.

          My tests was in ClientCnxnSocketNIO.doIO and NIOServerCnxn.doIO and it looks like they are going in silence. I'll do some more test tomorrow and report any discovery.

          Show
          Diego Oliveira added a comment - I did some testing and it appears to be something time related. Running a test in debug mode (ZooKeeperTest.testDeleteRecursive) sometimes works. Going a little deeper it looks like the channel is going in a broken state and the client can not send the next package. My tests was in ClientCnxnSocketNIO.doIO and NIOServerCnxn.doIO and it looks like they are going in silence. I'll do some more test tomorrow and report any discovery.
          Hide
          Ron Pressler added a comment -

          Running the server in Java 6 and the client in Java 7 seems to work fine.

          Show
          Ron Pressler added a comment - Running the server in Java 6 and the client in Java 7 seems to work fine.
          Hide
          Ron Pressler added a comment -

          Forgot to add - also a Macbook Pro.

          Show
          Ron Pressler added a comment - Forgot to add - also a Macbook Pro.
          Hide
          Ron Pressler added a comment -

          I'm seeing the same problem with OS X and JDK 7.

          Show
          Ron Pressler added a comment - I'm seeing the same problem with OS X and JDK 7.
          Hide
          Patrick Hunt added a comment -

          If you can attached logs from the failed test(s) that might give some insight. Compress it first though.

          Show
          Patrick Hunt added a comment - If you can attached logs from the failed test(s) that might give some insight. Compress it first though.
          Hide
          Diwaker Gupta added a comment -

          FWIW I upgraded to JDK 7u5 (from Oracle) and still have the exact same problem. Here are some of the tests that failed (within ZooKeeperTest):

          2012-06-15 13:59:58,654 [myid:] - INFO  [main:JUnit4ZKTestRunner$LoggedInvokeMethod@54] - TEST METHOD FAILED testDeleteRecursive
          2012-06-15 13:59:59,852 [myid:] - INFO  [main:ZKTestCase$1@66] - FAILED testDeleteRecursive
          2012-06-15 14:00:19,984 [myid:] - INFO  [main:JUnit4ZKTestRunner$LoggedInvokeMethod@54] - TEST METHOD FAILED testDeleteRecursiveAsync
          2012-06-15 14:00:21,097 [myid:] - INFO  [main:ZKTestCase$1@66] - FAILED testDeleteRecursiveAsync
          2012-06-15 14:00:41,225 [myid:] - INFO  [main:JUnit4ZKTestRunner$LoggedInvokeMethod@54] - TEST METHOD FAILED testStatWhenPathDoesNotExist
          2012-06-15 14:00:42,362 [myid:] - INFO  [main:ZKTestCase$1@66] - FAILED testStatWhenPathDoesNotExist
          2012-06-15 14:01:42,787 [myid:] - INFO  [main:JUnit4ZKTestRunner$LoggedInvokeMethod@54] - TEST METHOD FAILED testCreateNodeWithoutData
          2012-06-15 14:01:44,452 [myid:] - INFO  [main:ZKTestCase$1@66] - FAILED testCreateNodeWithoutData
          2012-06-15 14:02:04,577 [myid:] - INFO  [main:JUnit4ZKTestRunner$LoggedInvokeMethod@54] - TEST METHOD FAILED testACLWithExtraAgruments
          2012-06-15 14:02:05,749 [myid:] - INFO  [main:ZKTestCase$1@66] - FAILED testACLWithExtraAgruments
          2012-06-15 14:02:25,874 [myid:] - INFO  [main:JUnit4ZKTestRunner$LoggedInvokeMethod@54] - TEST METHOD FAILED testCreatePersistentNode
          2012-06-15 14:02:27,324 [myid:] - INFO  [main:ZKTestCase$1@66] - FAILED testCreatePersistentNode
          2012-06-15 14:02:47,449 [myid:] - INFO  [main:JUnit4ZKTestRunner$LoggedInvokeMethod@54] - TEST METHOD FAILED testDelete
          2012-06-15 14:02:48,585 [myid:] - INFO  [main:ZKTestCase$1@66] - FAILED testDelete
          2012-06-15 14:03:08,705 [myid:] - INFO  [main:JUnit4ZKTestRunner$LoggedInvokeMethod@54] - TEST METHOD FAILED testStatCommand
          2012-06-15 14:03:10,173 [myid:] - INFO  [main:ZKTestCase$1@66] - FAILED testStatCommand
          2012-06-15 14:03:30,295 [myid:] - INFO  [main:JUnit4ZKTestRunner$LoggedInvokeMethod@54] - TEST METHOD FAILED testInvalidStatCommand
          2012-06-15 14:03:31,688 [myid:] - INFO  [main:ZKTestCase$1@66] - FAILED testInvalidStatCommand
          2012-06-15 14:03:51,809 [myid:] - INFO  [main:JUnit4ZKTestRunner$LoggedInvokeMethod@54] - TEST METHOD FAILED testSetData
          2012-06-15 14:03:53,674 [myid:] - INFO  [main:ZKTestCase$1@66] - FAILED testSetData
          2012-06-15 14:04:13,836 [myid:] - INFO  [main:JUnit4ZKTestRunner$LoggedInvokeMethod@54] - TEST METHOD FAILED testDeleteWithInvalidVersionNo
          
          Show
          Diwaker Gupta added a comment - FWIW I upgraded to JDK 7u5 (from Oracle) and still have the exact same problem. Here are some of the tests that failed (within ZooKeeperTest): 2012-06-15 13:59:58,654 [myid:] - INFO [main:JUnit4ZKTestRunner$LoggedInvokeMethod@54] - TEST METHOD FAILED testDeleteRecursive 2012-06-15 13:59:59,852 [myid:] - INFO [main:ZKTestCase$1@66] - FAILED testDeleteRecursive 2012-06-15 14:00:19,984 [myid:] - INFO [main:JUnit4ZKTestRunner$LoggedInvokeMethod@54] - TEST METHOD FAILED testDeleteRecursiveAsync 2012-06-15 14:00:21,097 [myid:] - INFO [main:ZKTestCase$1@66] - FAILED testDeleteRecursiveAsync 2012-06-15 14:00:41,225 [myid:] - INFO [main:JUnit4ZKTestRunner$LoggedInvokeMethod@54] - TEST METHOD FAILED testStatWhenPathDoesNotExist 2012-06-15 14:00:42,362 [myid:] - INFO [main:ZKTestCase$1@66] - FAILED testStatWhenPathDoesNotExist 2012-06-15 14:01:42,787 [myid:] - INFO [main:JUnit4ZKTestRunner$LoggedInvokeMethod@54] - TEST METHOD FAILED testCreateNodeWithoutData 2012-06-15 14:01:44,452 [myid:] - INFO [main:ZKTestCase$1@66] - FAILED testCreateNodeWithoutData 2012-06-15 14:02:04,577 [myid:] - INFO [main:JUnit4ZKTestRunner$LoggedInvokeMethod@54] - TEST METHOD FAILED testACLWithExtraAgruments 2012-06-15 14:02:05,749 [myid:] - INFO [main:ZKTestCase$1@66] - FAILED testACLWithExtraAgruments 2012-06-15 14:02:25,874 [myid:] - INFO [main:JUnit4ZKTestRunner$LoggedInvokeMethod@54] - TEST METHOD FAILED testCreatePersistentNode 2012-06-15 14:02:27,324 [myid:] - INFO [main:ZKTestCase$1@66] - FAILED testCreatePersistentNode 2012-06-15 14:02:47,449 [myid:] - INFO [main:JUnit4ZKTestRunner$LoggedInvokeMethod@54] - TEST METHOD FAILED testDelete 2012-06-15 14:02:48,585 [myid:] - INFO [main:ZKTestCase$1@66] - FAILED testDelete 2012-06-15 14:03:08,705 [myid:] - INFO [main:JUnit4ZKTestRunner$LoggedInvokeMethod@54] - TEST METHOD FAILED testStatCommand 2012-06-15 14:03:10,173 [myid:] - INFO [main:ZKTestCase$1@66] - FAILED testStatCommand 2012-06-15 14:03:30,295 [myid:] - INFO [main:JUnit4ZKTestRunner$LoggedInvokeMethod@54] - TEST METHOD FAILED testInvalidStatCommand 2012-06-15 14:03:31,688 [myid:] - INFO [main:ZKTestCase$1@66] - FAILED testInvalidStatCommand 2012-06-15 14:03:51,809 [myid:] - INFO [main:JUnit4ZKTestRunner$LoggedInvokeMethod@54] - TEST METHOD FAILED testSetData 2012-06-15 14:03:53,674 [myid:] - INFO [main:ZKTestCase$1@66] - FAILED testSetData 2012-06-15 14:04:13,836 [myid:] - INFO [main:JUnit4ZKTestRunner$LoggedInvokeMethod@54] - TEST METHOD FAILED testDeleteWithInvalidVersionNo
          Hide
          Chris Carter added a comment -

          I don't have access to any Macs other than my Macbook Pro, so can't comment on cross-hardware. However, for awhile I was able to get an OpenJDK build to work properly under the conditions I was testing:

          openjdk version "1.7.0-b222"
          OpenJDK Runtime Environment (build 1.7.0-b222-20111220)
          OpenJDK 64-Bit Server VM (build 21.0-b17, mixed mode)

          All other Oracle and OpenJDK environments I've tried have failed.

          I'm running Lion 10.7.3 (had issues under 10.7.2 as well).

          Show
          Chris Carter added a comment - I don't have access to any Macs other than my Macbook Pro, so can't comment on cross-hardware. However, for awhile I was able to get an OpenJDK build to work properly under the conditions I was testing: openjdk version "1.7.0-b222" OpenJDK Runtime Environment (build 1.7.0-b222-20111220) OpenJDK 64-Bit Server VM (build 21.0-b17, mixed mode) All other Oracle and OpenJDK environments I've tried have failed. I'm running Lion 10.7.3 (had issues under 10.7.2 as well).
          Hide
          Diwaker Gupta added a comment -

          Scott: I've only tested this on my Mac and it happens fairly reliably. We have a few other Mac users who can also hit this.

          On a related note, one of my colleagues also ran into some failures on Linux, but it's not clear if the root cause was the same.

          Show
          Diwaker Gupta added a comment - Scott: I've only tested this on my Mac and it happens fairly reliably. We have a few other Mac users who can also hit this. On a related note, one of my colleagues also ran into some failures on Linux, but it's not clear if the root cause was the same.
          Hide
          Scott Lindner added a comment -

          I have also hit this and it's not something global across all Macs. I added details on the curator thread (https://github.com/Netflix/curator/issues/47#issuecomment-4706209) and admittedly this makes no sense to me but this seems to fail on all Mac laptops we have tried. However when I attempt this on my iMac it passes. Both environments are running the same MacOS and java version as well.

          Diwaker / Chris: what are your experiences?

          Show
          Scott Lindner added a comment - I have also hit this and it's not something global across all Macs. I added details on the curator thread ( https://github.com/Netflix/curator/issues/47#issuecomment-4706209 ) and admittedly this makes no sense to me but this seems to fail on all Mac laptops we have tried. However when I attempt this on my iMac it passes. Both environments are running the same MacOS and java version as well. Diwaker / Chris: what are your experiences?
          Hide
          Chris Carter added a comment -

          I've experienced this as well, as have a few other folks who use Curator. Will attempt to drag more out of the logs, if possible.

          Show
          Chris Carter added a comment - I've experienced this as well, as have a few other folks who use Curator. Will attempt to drag more out of the logs, if possible.
          Hide
          Patrick Hunt added a comment -

          Ah. Likely java7 on mac then. I don't know if anyone's tried that (I run linux on my laptop for most jdk7 local tests). You'd have to look at the logs and such to nail down more about that's going wrong.

          Show
          Patrick Hunt added a comment - Ah. Likely java7 on mac then. I don't know if anyone's tried that (I run linux on my laptop for most jdk7 local tests). You'd have to look at the logs and such to nail down more about that's going wrong.
          Hide
          Diwaker Gupta added a comment -

          Patrick: I believe the jenkins job runs on Linux. I'm running Java7 on Mac natively. Resources are not an issue: my machine as 8G of memory, runs on SSDs and there's no virtualization in the picture.

          Show
          Diwaker Gupta added a comment - Patrick: I believe the jenkins job runs on Linux. I'm running Java7 on Mac natively. Resources are not an issue: my machine as 8G of memory, runs on SSDs and there's no virtualization in the picture.
          Hide
          Patrick Hunt added a comment -

          ZK runs pretty cleanly against java7 on Apache jenkins:
          https://builds.apache.org//view/S-Z/view/ZooKeeper/job/ZooKeeper-trunk-jdk7/

          What's different about your environment? Perhaps you don't have sufficient resources to run (e.g. overloaded system? over virtualized, etc...)

          Show
          Patrick Hunt added a comment - ZK runs pretty cleanly against java7 on Apache jenkins: https://builds.apache.org//view/S-Z/view/ZooKeeper/job/ZooKeeper-trunk-jdk7/ What's different about your environment? Perhaps you don't have sufficient resources to run (e.g. overloaded system? over virtualized, etc...)

            People

            • Assignee:
              Unassigned
              Reporter:
              Diwaker Gupta
            • Votes:
              8 Vote for this issue
              Watchers:
              20 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development