[ZOOKEEPER-1661] Random (?) 5s delay when establishing connection

• Type: Bug
• Status: Open
• Priority: Major
• Resolution: Unresolved
• Affects Version/s: 3.4.5
• Component/s: server
• Assignee: Unassigned
• Reporter: Yan Pujante
• Created: 07/Mar/13 21:11
• Updated: 12/Mar/13 10:41

Description

I have a client connecting to ZooKeeper and I am sometimes seeing a 5s delay before the opening of the socket connection:

Here is the output on the client side:

2013/03/07 10:53:48.729 INFO [org.apache.zookeeper.ZooKeeper] Client environment:zookeeper.version=3.4.5-1392090, built on 09/30/2012 17:52 GMT
2013/03/07 10:53:48.729 INFO [org.apache.zookeeper.ZooKeeper] Client environment:host.name=xeon
2013/03/07 10:53:48.729 INFO [org.apache.zookeeper.ZooKeeper] Client environment:java.version=1.6.0_41
2013/03/07 10:53:48.729 INFO [org.apache.zookeeper.ZooKeeper] Client environment:java.vendor=Apple Inc.
2013/03/07 10:53:48.729 INFO [org.apache.zookeeper.ZooKeeper] Client environment:java.home=/System/Library/Java/JavaVirtualMachines/1.6.0.jdk/Contents/Home
2013/03/07 10:53:48.729 INFO [org.apache.zookeeper.ZooKeeper] Client environment:java.class.path=/local/java/lib/tools.jar:lib/ant-1.8.4.jar:lib/ant-antlr-1.8.4.jar:lib/ant-junit-1.8.4.jar:lib/ant-launcher-1.8.4.jar:lib/antlr-2.7.7.jar:lib/asm-4.0.jar:lib/asm-analysis-4.0.jar:lib/asm-commons-4.0.jar:lib/asm-tree-4.0.jar:lib/asm-util-4.0.jar:lib/commons-cli-1.2.jar:lib/groovy-2.0.7.jar:lib/groovy-ant-2.0.7.jar:lib/groovy-groovydoc-2.0.7.jar:lib/groovy-templates-2.0.7.jar:lib/groovy-xml-2.0.7.jar:lib/jackson-annotations-2.1.4.jar:lib/jackson-core-2.1.4.jar:lib/jackson-databind-2.1.4.jar:lib/jline-0.9.94.jar:lib/json-20090211.jar:lib/jul-to-slf4j-1.6.2.jar:lib/junit-3.8.1.jar:lib/log4j-1.2.16.jar:lib/netty-3.2.2.Final.jar:lib/org.linkedin.util-core-1.8.glu47.0.jar:lib/org.linkedin.util-groovy-1.8.glu47.0.jar:lib/org.linkedin.zookeeper-cli-impl-1.5.glu47.0-SNAPSHOT.jar:lib/org.linkedin.zookeeper-impl-1.5.glu47.0-SNAPSHOT.jar:lib/slf4j-api-1.6.2.jar:lib/slf4j-log4j12-1.6.2.jar:lib/zookeeper-3.4.5.jar
2013/03/07 10:53:48.730 INFO [org.apache.zookeeper.ZooKeeper] Client environment:java.library.path=/local/instantclient10:.:/Users/ypujante/Library/Java/Extensions:/Library/Java/Extensions:/System/Library/Java/Extensions:/usr/lib/java
2013/03/07 10:53:48.730 INFO [org.apache.zookeeper.ZooKeeper] Client environment:java.io.tmpdir=/var/folders/dj/qmkmx5648xjf2n006s7hc1v80000gq/T/
2013/03/07 10:53:48.730 INFO [org.apache.zookeeper.ZooKeeper] Client environment:java.compiler=<NA>
2013/03/07 10:53:48.730 INFO [org.apache.zookeeper.ZooKeeper] Client environment:os.name=Mac OS X
2013/03/07 10:53:48.730 INFO [org.apache.zookeeper.ZooKeeper] Client environment:os.arch=x86_64
2013/03/07 10:53:48.730 INFO [org.apache.zookeeper.ZooKeeper] Client environment:os.version=10.8.2
2013/03/07 10:53:48.730 INFO [org.apache.zookeeper.ZooKeeper] Client environment:user.name=ypujante
2013/03/07 10:53:48.730 INFO [org.apache.zookeeper.ZooKeeper] Client environment:user.home=/Users/ypujante
2013/03/07 10:53:48.730 INFO [org.apache.zookeeper.ZooKeeper] Client environment:user.dir=/export/content/linkedin-zookeeper/org.linkedin.zookeeper-cli-1.5.glu47.0-SNAPSHOT
2013/03/07 10:53:48.731 INFO [org.apache.zookeeper.ZooKeeper] Initiating client connection, connectString=localhost:2181 sessionTimeout=100 watcher=org.linkedin.zookeeper.client.ZKClient@3823bdd1
2013/03/07 10:53:48.737 DEBUG [org.apache.zookeeper.ClientCnxn] zookeeper.disableAutoWatchReset is false
2013/03/07 10:53:48.756 DEBUG [org.linkedin.zookeeper.cli.ClientMain] Talking to zookeeper on localhost:2181
2013/03/07 10:53:53.763 INFO [org.apache.zookeeper.ClientCnxn] Opening socket connection to server fe80:0:0:0:0:0:0:1%1/fe80:0:0:0:0:0:0:1%1:2181. Will not attempt to authenticate using SASL (Unable to locate a login configuration)

From this output you can see the line at 10:53:48 => Initiating client connection
And then 5s later, at 10:53:53 => opening socket connection

Note that I did not see this delay/problem prior to upgrading to 3.4.5 (from 3.3.3)

Also note that sometimes there is no delay as in the following output!

2013/03/07 11:04:06.084 INFO [org.apache.zookeeper.ZooKeeper] Initiating client connection, connectString=localhost:2181 sessionTimeout=100 watcher=org.linkedin.zookeeper.client.ZKClient@1e670479
2013/03/07 11:04:06.089 DEBUG [org.apache.zookeeper.ClientCnxn] zookeeper.disableAutoWatchReset is false
2013/03/07 11:04:06.109 DEBUG [org.linkedin.zookeeper.cli.ClientMain] Talking to zookeeper on localhost:2181
2013/03/07 11:04:06.116 INFO [org.apache.zookeeper.ClientCnxn] Opening socket connection to server localhost/0:0:0:0:0:0:0:1:2181. Will not attempt to authenticate using SASL (Unable to locate a login configuration)

I will be more than happy to provide more details if necessary. The client code is open source and hosted on github @ https://github.com/linkedin/linkedin-zookeeper/blob/master/org.linkedin.zookeeper-cli-impl/src/main/groovy/org/linkedin/zookeeper/cli/ClientMain.groovy#L65

and is not doing mech but (under the cover)

new ZooKeeper("localhost:2181", 100, watcher)

and then wait until the SyncConnected even is received...

Thanks
Yan

Issue Links

• is a clone of: ZOOKEEPER-1652 zookeeper java client does a reverse dns lookup when connecting
• relates to: ZOOKEEPER-1476 ipv6 reverse dns related timeouts on OSX connecting to localhost