[JCBC-151] Client does timeout on connect in specific java environments (was believed to be java7 related). Created: 21/Nov/12 Updated: 05/Apr/13 |
|
| Status: | Open |
| Project: | Couchbase Java Client |
| Component/s: | library |
| Affects Version/s: | 1.1-dp4 |
| Fix Version/s: | 1.1.6 |
| Security Level: | Public |
| Type: | Bug | Priority: | Critical |
| Reporter: | Michael Nitschinger | Assignee: | Michael Nitschinger |
| Resolution: | Unresolved | Votes: | 2 |
| Labels: | None | ||
| Remaining Estimate: | Not Specified | ||
| Time Spent: | Not Specified | ||
| Original Estimate: | Not Specified | ||
| Flagged: |
Release Note
|
| Description |
|
People report that the Client does not work with 1.7. Here is a sample stack trace:
2012-11-20 00:29:11.228 INFO com.couchbase.client.CouchbaseConnection: Added {QA sa=/127.0.0.1:11210, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0} to connect queue 2012-11-20 00:29:11.240 INFO com.couchbase.client.CouchbaseConnection: Connection state changed for sun.nio.ch.SelectionKeyImpl@3f757322 2012-11-20 00:29:11.502 INFO com.couchbase.client.ViewConnection: Added localhost/127.0.0.1:8092 to connect queue 2012-11-20 00:29:11.505 INFO com.couchbase.client.CouchbaseClient: viewmode property isn't defined. Setting viewmode to production mode 2012-11-20 00:29:11.647 INFO net.spy.memcached.auth.AuthThread: Authenticated to localhost/127.0.0.1:11210 2012-11-20 00:29:12.051 INFO com.couchbase.client.http.AsyncConnectionManager: Opening new Couchbase HTTP connection 2012-11-20 00:29:12.060 INFO com.couchbase.client.http.AsyncConnectionManager$ConnRequestCallback: localhost/127.0.0.1:8092 - Session request successful 2012-11-20 00:29:17.111 ERROR com.couchbase.client.ViewNode$EventLogger: Connection timed out: [localhost/127.0.0.1:8092(closed)] java.lang.RuntimeException: Timed out waiting for operation at com.couchbase.client.internal.HttpFuture.get(HttpFuture.java:68) at com.couchbase.client.CouchbaseClient.getView(CouchbaseClient.java:428) at Example1.main(Example1.java:43) Caused by: java.util.concurrent.TimeoutException: Timed out waiting for operation at com.couchbase.client.internal.HttpFuture.get(HttpFuture.java:80) at com.couchbase.client.internal.HttpFuture.get(HttpFuture.java:65) ... 2 more 2012-11-20 00:30:12.168 INFO com.couchbase.client.CouchbaseConnection: Shut down Couchbase client 2012-11-20 00:30:12.177 INFO com.couchbase.client.ViewNode: Couchbase I/O reactor terminated Disconnected from the target VM, address: '127.0.0.1:65280', transport: 'socket' Process finished with exit code 0 Also See http://www.couchbase.com/forums/thread/java-asyncconnectionmanager-timed-out-waiting-operation-please-help-console-log-included And http://stackoverflow.com/questions/13466010/using-java-api-in-scala-to-query-views-in-couchbase-throws-timeout-exception?utm_source=twitterfeed&utm_medium=twitter |
| Comments |
| Comment by Quinn Slack [ 27/Nov/12 ] |
|
This doesn't appear to be strictly related to Java7. I was able to get similar code to work on Java7. I even simulated loading a Play2 environment with other JARs that could potentially cause conflicts. It's possible that my simulation of the Play2 environment was insufficient and that Play2 does other stuff...
Code at https://github.com/sqs/couchbase-scala-example. Run with: CBURL=http://localhost:8091/pools CBPASSWORD=mypassword sbt -Dconfig.file=conf/application.conf '~run' Here is the output on my system that shows it's on Java7 (openjdk) and that shows the expected output from the views: on java version 1.7.0_09 [info] play - Application started (Prod) 2012-11-27 01:34:27.115 INFO com.couchbase.client.CouchbaseConnection: Added {QA sa=/127.0.0.1:11210, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0} to connect queue 2012-11-27 01:34:27.120 INFO com.couchbase.client.CouchbaseConnection: Connection state changed for sun.nio.ch.SelectionKeyImpl@6267e5a2 2012-11-27 01:34:27.147 INFO com.couchbase.client.ViewConnection: Added localhost/127.0.0.1:8092 to connect queue 2012-11-27 01:34:27.149 INFO com.couchbase.client.CouchbaseClient: viewmode property isn't defined. Setting viewmode to production mode 2012-11-27 01:34:27.176 INFO net.spy.memcached.auth.AuthThread: Authenticated to localhost/127.0.0.1:11210 2012-11-27 01:34:27.282 INFO com.couchbase.client.http.AsyncConnectionManager: Opening new Couchbase HTTP connection 2012-11-27 01:34:27.288 INFO com.couchbase.client.http.AsyncConnectionManager$ConnRequestCallback: localhost/127.0.0.1:8092 - Session request successful Res = List(com.couchbase.client.protocol.views.ViewRowNoDocs@4667820f, com.couchbase.client.protocol.views.ViewRowNoDocs@358bcae5, com.couchbase.client.protocol.views.ViewRowNoDocs@6cb59bd9, com.couchbase.client.protocol.views.ViewRowNoDocs@70afb51, com.couchbase.client.protocol.views.ViewRowNoDocs@61f98673) 2012-11-27 01:34:27.396 INFO com.couchbase.client.CouchbaseConnection: Shut down Couchbase client 2012-11-27 01:34:27.403 INFO com.couchbase.client.ViewNode: Couchbase I/O reactor terminated |
| Comment by Michael Nitschinger [ 27/Nov/12 ] |
| Are you running on jdk7 on mac? Also, when you use play 2.1 it should work. Play2-related issues more were because of netty version incompatibilities. |
| Comment by Quinn Slack [ 27/Nov/12 ] |
|
This is jdk7 on Arch Linux and Play 2.1-RC1.
I tried using a different netty, but no luck. What worked for me was moving calls to "new CouchbaseClient" out of static "object" initializers, since they appeared to be getting called in the Netty I/O thread (I got this exception in new CouchbaseClient: java.lang.IllegalStateException: await*() in I/O thread causes a dead lock or sudden performance drop. Use addListener() instead or call await*() from a different thread). |
| Comment by Michael Nitschinger [ 28/Nov/12 ] |
| Hi Quinn, this issue is a different one! The issue described here is that people seem to find connection timeouts with java 7. |
| Comment by Quinn Slack [ 28/Nov/12 ] |
| They may be related--or may just have similar symptoms. I was not getting timeout exceptions, but I was seeing view requests hang indefinitely until I made the fix described above. |
| Comment by dragos [ 13/Mar/13 ] |
|
Hi Michael, can you help with this error ? I am trying to find a workaround or something to work. This is the only thing which is keeping us from using Couchbase. I also posted here : http://www.couchbase.com/forums/thread/couchbase-connectivity-problem-aws-vpc . As you can see in the times the timeout is received really fast. 2013-03-13 11:40:47.702 INFO com.couchbase.client.CouchbaseConnection: Added {QA sa=/10.0.X.XXX:11210, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0} to connect queue 2013-03-13 11:40:52.712 INFO com.couchbase.client.CouchbaseConnection: Connection state changed for sun.nio.ch.SelectionKeyImpl@5cbfe9d 2013-03-13 11:40:52.840 INFO net.spy.memcached.auth.AuthThread: Authenticated to 10.0.X.XXX/10.0.X.XXX:11210 2013-03-13 11:40:57.860 INFO com.couchbase.client.ViewConnection: Added 10.0.X.XXX to connect queue 2013-03-13 11:40:57.863 INFO com.couchbase.client.CouchbaseClient: viewmode property isn't defined. Setting viewmode to production mode 2013-03-13 11:40:58.070 INFO com.couchbase.client.http.AsyncConnectionManager: Opening new Couchbase HTTP connection 2013-03-13 11:40:58.077 INFO com.couchbase.client.http.AsyncConnectionManager$ConnRequestCallback: /10.0.X.XXX:8092 - Session request successful 2013-03-13 11:41:03.113 ERROR com.couchbase.client.ViewNode$EventLogger: Connection timed out: [10.0.X.XXX/10.0.X.XXX:8092] Exception in thread "main" java.lang.RuntimeException: Timed out waiting for operation at com.couchbase.client.internal.HttpFuture.get(HttpFuture.java:67) at com.couchbase.client.CouchbaseClient.getView(CouchbaseClient.java:475) at couchbase.training.view.poc.CouchbasePOC.main(CouchbasePOC.java:63) Caused by: java.util.concurrent.TimeoutException: Timed out waiting for operation at com.couchbase.client.internal.HttpFuture.waitForAndCheckOperation(HttpFuture.java:85) at com.couchbase.client.internal.HttpFuture.get(HttpFuture.java:74) at com.couchbase.client.internal.HttpFuture.get(HttpFuture.java:64) |
| Comment by Michael Nitschinger [ 13/Mar/13 ] |
|
Hi dragos, can you please post the full code where you connect to couchbase? (including factories and such) Thanks! |
| Comment by dragos [ 13/Mar/13 ] |
|
Hi Mike, this is the POC client for Couchbase: package couchbase.training.view.poc; import java.io.FileInputStream; import java.io.FileNotFoundException; import java.io.IOException; import java.net.URI; import java.util.LinkedList; import java.util.List; import java.util.concurrent.TimeUnit; import org.apache.commons.io.IOUtils; import org.json.JSONException; import org.json.XML; import com.couchbase.client.CouchbaseClient; import com.couchbase.client.CouchbaseConnectionFactory; import com.couchbase.client.CouchbaseConnectionFactoryBuilder; import com.couchbase.client.protocol.views.ComplexKey; import com.couchbase.client.protocol.views.Query; import com.couchbase.client.protocol.views.Stale; import com.couchbase.client.protocol.views.View; import com.couchbase.client.protocol.views.ViewResponse; import com.couchbase.client.protocol.views.ViewRow; public class CouchbasePOC { public static void main(String[] args) throws FileNotFoundException, JSONException, IOException { System.out.println("Hello from CouchBase"); // Set the URIs and get a client final List<URI> uris = new LinkedList<URI>(); // Connect to localhost or to the appropriate URI(s) uris.add(URI.create("http://10.0.7.164:8091/pools")); final String mappedName="problems"; long start = System.currentTimeMillis(); CouchbaseConnectionFactoryBuilder m_couchbaseConnectionFactoryBuilder = new CouchbaseConnectionFactoryBuilder(); m_couchbaseConnectionFactoryBuilder.setMaxReconnectDelay(10000); m_couchbaseConnectionFactoryBuilder.setOpQueueMaxBlockTime(100); m_couchbaseConnectionFactoryBuilder.setOpTimeout(20000); m_couchbaseConnectionFactoryBuilder.setShouldOptimize(true); m_couchbaseConnectionFactoryBuilder.setViewTimeout(300000); CouchbaseConnectionFactory connFactory = m_couchbaseConnectionFactoryBuilder.buildCouchbaseConnection(uris, mappedName, ""); CouchbaseClient client = null; try { client = new CouchbaseClient(connFactory); } catch (IOException e) { System.err.println("IOException connecting to Couchbase: " + e.getMessage()); System.exit(1); } final View view = client.getView(mappedName, mappedName); final Query query = new Query(); final ComplexKey key = ComplexKey.of("problem",null,null,null,null); query.setKey(key); query.setStale( Stale.UPDATE_AFTER ); int counter=0; try { final ViewResponse result = client.query(view, query); for(ViewRow row : result) { counter++; System.out.println(row.getId()); } } catch(java.lang.VerifyError e) { System.out.println("Error: " + e.getMessage()); } System.out.println("time: " + (System.currentTimeMillis()-start) ); System.out.println("documents: " + counter ); client.shutdown(3, TimeUnit.SECONDS); System.exit(0); } } |
| Comment by dragos [ 13/Mar/13 ] |
| I hope you would not mind that i called you Mike and not Michael. |
| Comment by Michael Nitschinger [ 13/Mar/13 ] |
|
Hehe no worries. Can you do me a favor and remove the factory for a second and just use CouchbaseClient() without anything else? Let me know if the problem still persists or not! Thanks |
| Comment by dragos [ 13/Mar/13 ] |
|
Hi Michael, First i want to thank you for the quick feed-back. Your owesome !!! Before using the factory i used the CouchbaseClient(uris, bucketName, "") which is also timing out. I added the factory to be able increase the timeout times for the connection but still the same problem. |
| Comment by Michael Nitschinger [ 13/Mar/13 ] |
|
Hmm okay, so its not the factory (we had some issues with default values in the past, thats why I'm asking). Can you pin me down your operating system and exact java version you're using?Thanks for your help! |
| Comment by Michael Nitschinger [ 13/Mar/13 ] |
|
Also, since you're so responsive (I hope we can pin this down finally!).. Can you run the same code with DEBUG log enabled (see https://code.google.com/p/spymemcached/wiki/Logging).. just use Logger.getLogger("com.couchbase.client").setLevel(Level.FINEST); instead of Logger.getLogger("net.spy.memcached").setLevel(Level.FINEST); Thanks! |
| Comment by dragos [ 13/Mar/13 ] |
|
This is my test environment for the client which will be similar for production. OS Ubuntu Server 11.10 x64 java -version result: java version "1.6.0_26" Java(TM) SE Runtime Environment (build 1.6.0_26-b03) Java HotSpot(TM) 64-Bit Server VM (build 20.1-b02, mixed mode) My network infrastructure is like this: In an AWS virtual private center (VPC) i have a subnet and in this subnet there are 2 machines. The client machine and the Couchbase server. The machines have identical OS and java version as mentioned above. I have open the ports and also checked the network ACL. The traffic is free to go,no restriction. If i am using a rest query with curl for the view i receive the result, the problem is only in the java SDK. If needed more information please ask. I will gladly offer it. |
| Comment by Michael Nitschinger [ 13/Mar/13 ] |
|
Hi Dragos,
yes, if you can please rerun the script with DEBUG logging enabled (see last comment).. Thanks very much in advance! |
| Comment by dragos [ 13/Mar/13 ] |
|
I've setted the logger to finest and this is the error log obtained. Also i tested again the connection with curl and no problemes. Mar 13, 2013 1:30:14 PM com.couchbase.client.CouchbaseProperties setPropertyFile INFO: Could not load properties file "cbclient.properties" because: File not found with system classloader. 2013-03-13 13:30:14.679 INFO com.couchbase.client.CouchbaseConnection: Added {QA sa=/10.0.7.164:11210, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0} to connect queue 2013-03-13 13:30:19.689 INFO com.couchbase.client.CouchbaseConnection: Connection state changed for sun.nio.ch.SelectionKeyImpl@4e99353f 2013-03-13 13:30:19.810 INFO net.spy.memcached.auth.AuthThread: Authenticated to 10.0.7.164/10.0.7.164:11210 2013-03-13 13:30:24.828 INFO com.couchbase.client.ViewConnection: Added 10.0.7.164 to connect queue 2013-03-13 13:30:24.830 INFO com.couchbase.client.CouchbaseClient: viewmode property isn't defined. Setting viewmode to production mode 2013-03-13 13:30:25.025 INFO com.couchbase.client.http.AsyncConnectionManager: Opening new Couchbase HTTP connection 2013-03-13 13:30:25.033 INFO com.couchbase.client.http.AsyncConnectionManager$ConnRequestCallback: /10.0.7.164:8092 - Session request successful 2013-03-13 13:30:30.083 ERROR com.couchbase.client.ViewNode$EventLogger: Connection timed out: [10.0.7.164/10.0.7.164:8092] Exception in thread "main" java.lang.RuntimeException: Timed out waiting for operation at com.couchbase.client.internal.HttpFuture.get(HttpFuture.java:67) at com.couchbase.client.CouchbaseClient.getView(CouchbaseClient.java:475) at couchbase.training.view.poc.CouchbasePOC.main(CouchbasePOC.java:68) Caused by: java.util.concurrent.TimeoutException: Timed out waiting for operation at com.couchbase.client.internal.HttpFuture.waitForAndCheckOperation(HttpFuture.java:85) at com.couchbase.client.internal.HttpFuture.get(HttpFuture.java:74) at com.couchbase.client.internal.HttpFuture.get(HttpFuture.java:64) ... 2 more curl result curl http://10.0.7.164:8092/problems/_design/dev_problems/_view/problems?stale=false\&connection_timeout=60000\&limit=10\&skip=0 {"total_rows":0,"rows":[ ] } [4]+ Done |
| Comment by dragos [ 13/Mar/13 ] |
| I am available for next steps in debuging. With what can i help next ? |
| Comment by Michael Nitschinger [ 13/Mar/13 ] |
|
Hi, hmm no there should be more output (DEBUG), not just info... you need to copy this whole snippet before your code actually executes: // Tell spy to use the SunLogger Properties systemProperties = System.getProperties(); systemProperties.put("net.spy.log.LoggerImpl", "net.spy.memcached.compat.log.SunLogger"); System.setProperties(systemProperties); Logger.getLogger("com.couchbase.client").setLevel(Level.FINEST); //get the top Logger Logger topLogger = java.util.logging.Logger.getLogger(""); // Handler for console (reuse it if it already exists) Handler consoleHandler = null; //see if there is already a console handler for (Handler handler : topLogger.getHandlers()) { if (handler instanceof ConsoleHandler) { //found the console handler consoleHandler = handler; break; } } if (consoleHandler == null) { //there was no console handler found, create a new one consoleHandler = new ConsoleHandler(); topLogger.addHandler(consoleHandler); } //set the console handler to fine: consoleHandler.setLevel(java.util.logging.Level.FINEST); I guess you're running it from your IDE? |
| Comment by dragos [ 13/Mar/13 ] |
|
I am building the client on local IDE then uploading it to EC2 test machine. The snipped of code word and now i have a full log. Mar 13, 2013 1:53:10 PM com.couchbase.client.CouchbaseProperties setPropertyFile INFO: Could not load properties file "cbclient.properties" because: File not found with system classloader. Mar 13, 2013 1:53:11 PM com.couchbase.client.vbucket.ConfigurationProviderHTTP readToString FINE: Attempting to read configuration from URI: http://10.0.7.164:8091/pools Mar 13, 2013 1:53:11 PM com.couchbase.client.vbucket.ConfigurationProviderHTTP readToString FINE: Attempting to read configuration from URI: http://10.0.7.164:8091/pools/default?uuid=44b1e62dd7e65cd38ae7faaabe5ebb64 Mar 13, 2013 1:53:11 PM com.couchbase.client.vbucket.ConfigurationProviderHTTP readToString FINE: Attempting to read configuration from URI: http://10.0.7.164:8091/pools/default/buckets?v=120523822&uuid=44b1e62dd7e65cd38ae7faaabe5ebb64 Mar 13, 2013 1:53:11 PM net.spy.memcached.MemcachedConnection createConnections INFO: Added {QA sa=/10.0.7.164:11210, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0} to connect queue Mar 13, 2013 1:53:11 PM com.couchbase.client.vbucket.VBucketNodeLocator fillNodesEntries FINE: Updating nodesMap in VBucketNodeLocator. Mar 13, 2013 1:53:16 PM com.couchbase.client.vbucket.VBucketNodeLocator fillNodesEntries FINE: Adding node with address 10.0.7.164:11210. Mar 13, 2013 1:53:16 PM com.couchbase.client.vbucket.VBucketNodeLocator fillNodesEntries FINE: Node added is {QA sa=10.0.7.164/10.0.7.164:11210, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=8}. Mar 13, 2013 1:53:16 PM net.spy.memcached.MemcachedConnection handleIO FINE: Done dealing with queue. Mar 13, 2013 1:53:16 PM net.spy.memcached.MemcachedConnection handleIO FINE: Selecting with delay of 0ms Mar 13, 2013 1:53:16 PM net.spy.memcached.MemcachedConnection handleIO FINE: Selected 1, selected 1 keys Mar 13, 2013 1:53:16 PM net.spy.memcached.MemcachedConnection handleIO FINE: Handling IO for: sun.nio.ch.SelectionKeyImpl@2c76e369 (r=false, w=false, c=true, op={QA sa=10.0.7.164/10.0.7.164:11210, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=8}) Mar 13, 2013 1:53:16 PM net.spy.memcached.MemcachedConnection handleIO INFO: Connection state changed for sun.nio.ch.SelectionKeyImpl@2c76e369 Mar 13, 2013 1:53:16 PM net.spy.memcached.MemcachedConnection insertOperation FINE: Added Cmd: 10 Opaque: 1 to {QA sa=10.0.7.164/10.0.7.164:11210, #Rops=0, #Wops=0, #iq=1, topRop=null, topWop=null, toWrite=0, interested=8} Mar 13, 2013 1:53:16 PM net.spy.memcached.MemcachedConnection handleReads FINE: Read 24 bytes Mar 13, 2013 1:53:16 PM net.spy.memcached.MemcachedConnection handleReads FINE: Completed read op: Cmd: 10 Opaque: 1 and giving the next 0 bytes Mar 13, 2013 1:53:16 PM net.spy.memcached.MemcachedConnection handleInputQueue FINE: Handling queue Mar 13, 2013 1:53:16 PM net.spy.memcached.MemcachedConnection handleIO FINE: Done dealing with queue. Mar 13, 2013 1:53:16 PM net.spy.memcached.MemcachedConnection handleIO FINE: Selecting with delay of 0ms Mar 13, 2013 1:53:16 PM net.spy.memcached.MemcachedConnection handleIO FINE: No selectors ready, interrupted: false Mar 13, 2013 1:53:16 PM net.spy.memcached.MemcachedConnection handleIO FINE: Done dealing with queue. Mar 13, 2013 1:53:16 PM net.spy.memcached.MemcachedConnection handleIO FINE: Selecting with delay of 0ms Mar 13, 2013 1:53:16 PM net.spy.memcached.MemcachedConnection handleIO FINE: No selectors ready, interrupted: false Mar 13, 2013 1:53:16 PM net.spy.memcached.MemcachedConnection handleInputQueue FINE: Handling queue Mar 13, 2013 1:53:16 PM net.spy.memcached.MemcachedConnection handleIO FINE: Done dealing with queue. Mar 13, 2013 1:53:16 PM net.spy.memcached.MemcachedConnection handleIO FINE: Selecting with delay of 0ms Mar 13, 2013 1:53:16 PM net.spy.memcached.MemcachedConnection handleIO FINE: Selected 1, selected 1 keys Mar 13, 2013 1:53:16 PM net.spy.memcached.MemcachedConnection insertOperation FINE: Added SASL auth operation to {QA sa=10.0.7.164/10.0.7.164:11210, #Rops=0, #Wops=1, #iq=0, topRop=null, topWop=SASL auth operation, toWrite=0, interested=4} Mar 13, 2013 1:53:16 PM net.spy.memcached.MemcachedConnection handleIO FINE: Handling IO for: sun.nio.ch.SelectionKeyImpl@2c76e369 (r=false, w=true, c=false, op={QA sa=10.0.7.164/10.0.7.164:11210, #Rops=0, #Wops=1, #iq=0, topRop=null, topWop=SASL auth operation, toWrite=0, interested=4}) Mar 13, 2013 1:53:16 PM net.spy.memcached.MemcachedConnection handleIO FINE: Done dealing with queue. Mar 13, 2013 1:53:16 PM net.spy.memcached.MemcachedConnection handleIO FINE: Selecting with delay of 0ms Mar 13, 2013 1:53:16 PM net.spy.memcached.MemcachedConnection handleIO FINE: Selected 1, selected 1 keys Mar 13, 2013 1:53:16 PM net.spy.memcached.MemcachedConnection handleIO FINE: Handling IO for: sun.nio.ch.SelectionKeyImpl@2c76e369 (r=true, w=false, c=false, op={QA sa=10.0.7.164/10.0.7.164:11210, #Rops=1, #Wops=0, #iq=0, topRop=SASL auth operation, topWop=null, toWrite=0, interested=1}) Mar 13, 2013 1:53:16 PM net.spy.memcached.MemcachedConnection handleReads FINE: Read 37 bytes Mar 13, 2013 1:53:16 PM net.spy.memcached.auth.AuthThread$1 receivedStatus INFO: Authenticated to 10.0.7.164/10.0.7.164:11210 Mar 13, 2013 1:53:16 PM net.spy.memcached.MemcachedConnection handleReads FINE: Completed read op: SASL auth operation and giving the next 0 bytes Mar 13, 2013 1:53:16 PM net.spy.memcached.MemcachedConnection handleIO FINE: Done dealing with queue. Mar 13, 2013 1:53:16 PM net.spy.memcached.MemcachedConnection handleIO FINE: Selecting with delay of 0ms Mar 13, 2013 1:53:21 PM com.couchbase.client.ViewConnection createConnections INFO: Added 10.0.7.164 to connect queue Mar 13, 2013 1:53:21 PM com.couchbase.client.CouchbaseClient <init> INFO: viewmode property isn't defined. Setting viewmode to production mode Mar 13, 2013 1:53:21 PM com.couchbase.client.vbucket.ConfigurationProviderHTTP subscribe FINE: Subscribing an object for reconfiguration updates com.couchbase.client.CouchbaseClient Mar 13, 2013 1:53:21 PM com.couchbase.client.vbucket.BucketUpdateResponseHandler handleUpstream FINEST: Channel state changed: [id: 0x2e273686] OPEN Mar 13, 2013 1:53:21 PM com.couchbase.client.vbucket.BucketUpdateResponseHandler handleUpstream FINER: Channel state change is not a disconnect. Event value is true and Channel State is OPEN. Mar 13, 2013 1:53:21 PM com.couchbase.client.vbucket.BucketUpdateResponseHandler handleUpstream FINEST: Channel state changed: [id: 0x2e273686, /10.0.7.213:55729 => /10.0.7.164:8091] BOUND: /10.0.7.213:55729 Mar 13, 2013 1:53:21 PM com.couchbase.client.vbucket.BucketUpdateResponseHandler handleUpstream FINER: Channel state change is not a disconnect. Event value is /10.0.7.213:55729 and Channel State is BOUND. Mar 13, 2013 1:53:21 PM com.couchbase.client.vbucket.BucketUpdateResponseHandler handleUpstream FINEST: Channel state changed: [id: 0x2e273686, /10.0.7.213:55729 => /10.0.7.164:8091] CONNECTED: /10.0.7.164:8091 Mar 13, 2013 1:53:21 PM com.couchbase.client.vbucket.BucketUpdateResponseHandler handleUpstream FINER: Channel state change is not a disconnect. Event value is /10.0.7.164:8091 and Channel State is CONNECTED. Mar 13, 2013 1:53:21 PM com.couchbase.client.vbucket.BucketUpdateResponseHandler finerLog FINER: STATUS: 200 OK Mar 13, 2013 1:53:21 PM com.couchbase.client.vbucket.BucketUpdateResponseHandler finerLog FINER: VERSION: HTTP/1.1 Mar 13, 2013 1:53:21 PM com.couchbase.client.vbucket.BucketUpdateResponseHandler finerLog FINER: HEADER: Cache-Control = no-cache Mar 13, 2013 1:53:21 PM com.couchbase.client.vbucket.BucketUpdateResponseHandler finerLog FINER: HEADER: Content-Type = application/json; charset=utf-8 Mar 13, 2013 1:53:21 PM com.couchbase.client.vbucket.BucketUpdateResponseHandler finerLog FINER: HEADER: Date = Wed, 13 Mar 2013 13:55:42 GMT Mar 13, 2013 1:53:21 PM com.couchbase.client.vbucket.BucketUpdateResponseHandler finerLog FINER: HEADER: Pragma = no-cache Mar 13, 2013 1:53:21 PM com.couchbase.client.vbucket.BucketUpdateResponseHandler finerLog FINER: HEADER: Server = Couchbase Server 2.0.0-1976-rel-enterprise Mar 13, 2013 1:53:21 PM com.couchbase.client.vbucket.BucketUpdateResponseHandler finerLog FINER: HEADER: Transfer-Encoding = chunked Mar 13, 2013 1:53:21 PM com.couchbase.client.vbucket.BucketUpdateResponseHandler finerLog FINER: Mar 13, 2013 1:53:21 PM com.couchbase.client.vbucket.BucketUpdateResponseHandler finerLog FINER: CHUNKED CONTENT { Mar 13, 2013 1:53:21 PM com.couchbase.client.vbucket.BucketUpdateResponseHandler finerLog FINER: {"name":"problems","bucketType":"membase","authType":"sasl","saslPassword":"","proxyPort":0,"replicaIndex":false,"uri":"/pools/default/buckets/problems?bucket_uuid=7675b7791efe17220792c2b41ff6c824","streamingUri":"/pools/default/bucketsStreaming/problems?bucket_uuid=7675b7791efe17220792c2b41ff6c824","localRandomKeyUri":"/pools/default/buckets/problems/localRandomKey","controllers":{"compactAll":"/pools/default/buckets/problems/controller/compactBucket","compactDB":"/pools/default/buckets/problems/controller/compactDatabases"},"nodes":[{"couchApiBase":"http://10.0.7.164:8092/problems","replication":0.0,"clusterMembership":"active","status":"healthy","thisNode":true,"hostname":"10.0.7.164:8091","clusterCompatibility":131072,"version":"2.0.0-1976-rel-enterprise","os":"x86_64-unknown-linux-gnu","ports":{"proxy":11211,"direct":11210}}],"stats":{"uri":"/pools/default/buckets/problems/stats","directoryURI":"/pools/default/buckets/problems/statsDirectory","nodeStatsListURI":"/pools/default/buckets/problems/nodes"},"ddocs":{"uri":"/pools/default/buckets/problems/ddocs"},"nodeLocator":"vbucket","autoCompactionSettings":false,"fastWarmupSettings":false,"uuid":"7675b7791efe17220792c2b41ff6c824","vBucketServerMap":{"hashAlgorithm":"CRC","numReplicas":1,"serverList":["10.0.7.164:11210"],"vBucketMap":[[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[ Mar 13, 2013 1:53:21 PM com.couchbase.client.vbucket.BucketUpdateResponseHandler finerLog FINER: Chunk length is: 3066 Mar 13, 2013 1:53:21 PM com.couchbase.client.vbucket.BucketUpdateResponseHandler finerLog FINER: 0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1 Mar 13, 2013 1:53:21 PM com.couchbase.client.vbucket.BucketUpdateResponseHandler finerLog FINER: Chunk length is: 2048 Mar 13, 2013 1:53:21 PM com.couchbase.client.vbucket.BucketUpdateResponseHandler finerLog FINER: ],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,- Mar 13, 2013 1:53:21 PM com.couchbase.client.vbucket.BucketUpdateResponseHandler finerLog FINER: Chunk length is: 3072 Mar 13, 2013 1:53:21 PM com.couchbase.client.vbucket.BucketUpdateResponseHandler finerLog FINER: 1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1]]},"bucketCapabilitiesVer":"","bucketCapabilities":["touch","couchapi"]} Mar 13, 2013 1:53:21 PM com.couchbase.client.vbucket.BucketUpdateResponseHandler finerLog FINER: Chunk length is: 361 Mar 13, 2013 1:53:21 PM com.couchbase.client.vbucket.BucketMonitor logFiner FINER: Getting server list returns this last chunked response: {"name":"problems","bucketType":"membase","authType":"sasl","saslPassword":"","proxyPort":0,"replicaIndex":false,"uri":"/pools/default/buckets/problems?bucket_uuid=7675b7791efe17220792c2b41ff6c824","streamingUri":"/pools/default/bucketsStreaming/problems?bucket_uuid=7675b7791efe17220792c2b41ff6c824","localRandomKeyUri":"/pools/default/buckets/problems/localRandomKey","controllers":{"compactAll":"/pools/default/buckets/problems/controller/compactBucket","compactDB":"/pools/default/buckets/problems/controller/compactDatabases"},"nodes":[{"couchApiBase":"http://10.0.7.164:8092/problems","replication":0.0,"clusterMembership":"active","status":"healthy","thisNode":true,"hostname":"10.0.7.164:8091","clusterCompatibility":131072,"version":"2.0.0-1976-rel-enterprise","os":"x86_64-unknown-linux-gnu","ports":{"proxy":11211,"direct":11210}}],"stats":{"uri":"/pools/default/buckets/problems/stats","directoryURI":"/pools/default/buckets/problems/statsDirectory","nodeStatsListURI":"/pools/default/buckets/problems/nodes"},"ddocs":{"uri":"/pools/default/buckets/problems/ddocs"},"nodeLocator":"vbucket","autoCompactionSettings":false,"fastWarmupSettings":false,"uuid":"7675b7791efe17220792c2b41ff6c824","vBucketServerMap":{"hashAlgorithm":"CRC","numReplicas":1,"serverList":["10.0.7.164:11210"],"vBucketMap":[[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1],[0,-1]]},"bucketCapabilitiesVer":"","bucketCapabilities":["touch","couchapi"]} Mar 13, 2013 1:53:21 PM com.couchbase.client.vbucket.ReconfigurableObserver update FINEST: Received an update, notifying reconfigurables about a com.couchbase.client.vbucket.config.Bucketcom.couchbase.client.vbucket.config.Bucket@4cf3fdc4 Mar 13, 2013 1:53:21 PM com.couchbase.client.vbucket.ReconfigurableObserver update FINEST: It says it is problems and it's talking to /pools/default/bucketsStreaming/problems?bucket_uuid=7675b7791efe17220792c2b41ff6c824 Mar 13, 2013 1:53:21 PM com.couchbase.client.CouchbaseConnection reconfigure FINE: Node 10.0.7.164/10.0.7.164:11210 will stay in cluster config after reconfiguration. Mar 13, 2013 1:53:21 PM com.couchbase.client.vbucket.VBucketNodeLocator updateLocator FINE: Received updated configuration with insignificant changes. Mar 13, 2013 1:53:21 PM com.couchbase.client.vbucket.ReconfigurableObserver update FINEST: Received an update, notifying reconfigurables about a com.couchbase.client.vbucket.config.Bucketcom.couchbase.client.vbucket.config.Bucket@fadb83cf Mar 13, 2013 1:53:21 PM com.couchbase.client.vbucket.ReconfigurableObserver update FINEST: It says it is problems and it's talking to /pools/default/bucketsStreaming/problems?bucket_uuid=7675b7791efe17220792c2b41ff6c824 Mar 13, 2013 1:53:21 PM com.couchbase.client.CouchbaseConnection reconfigure FINE: Node 10.0.7.164/10.0.7.164:11210 will stay in cluster config after reconfiguration. Mar 13, 2013 1:53:21 PM com.couchbase.client.vbucket.VBucketNodeLocator updateLocator FINE: Received updated configuration with insignificant changes. Mar 13, 2013 1:53:21 PM com.couchbase.client.http.AsyncConnectionManager processConnectionRequests INFO: Opening new Couchbase HTTP connection Mar 13, 2013 1:53:21 PM com.couchbase.client.http.AsyncConnectionManager$ConnRequestCallback completed INFO: /10.0.7.164:8092 - Session request successful Mar 13, 2013 1:53:21 PM com.couchbase.client.ViewNode$EventLogger connectionOpen FINE: Connection open: [/10.0.7.164:8092] Mar 13, 2013 1:53:26 PM com.couchbase.client.ViewNode$EventLogger connectionTimeout SEVERE: Connection timed out: [10.0.7.164/10.0.7.164:8092] Mar 13, 2013 1:53:26 PM com.couchbase.client.ViewNode$EventLogger connectionClosed FINE: Connection closed: [10.0.7.164/10.0.7.164:8092(closed)] |
| Comment by Michael Nitschinger [ 13/Mar/13 ] |
|
Hi, thanks for the log.. interestingly, there is nothing unusual in this.. I'll investigate further and come back to you if I need more info.. thanks so far! |
| Comment by dragos [ 13/Mar/13 ] |
| Thank you for spending time on this. Looking forward for a fix :) . |
| Comment by Michael Nitschinger [ 13/Mar/13 ] |
|
interestingly, the connection is open and then times out... INFO: /10.0.7.164:8092 - Session request successful Mar 13, 2013 1:53:21 PM com.couchbase.client.ViewNode$EventLogger connectionOpen FINE: Connection open: [/10.0.7.164:8092] Mar 13, 2013 1:53:26 PM com.couchbase.client.ViewNode$EventLogger connectionTimeout SEVERE: Connection timed out: [10.0.7.164/10.0.7.164:8092] Mar 13, 2013 1:53:26 PM com.couchbase.client.ViewNode$EventLogger connectionClosed FINE: Connection closed: [10.0.7.164/10.0.7.164:8092(closed)] this sounds highly suspicious to me, maybe this is a bug in apache httpcore-nio... |
| Comment by dragos [ 13/Mar/13 ] |
| The time out is displayed after 5 seconds. As you suggested i removed the factory and the detailed logged above i obtained with using CouchbaseClient(uris, mappedName, ""). Do you have some way of testing the httpCore-nio ? Should i try to look for latest version of httpCore-nio.. ? |
| Comment by Michael Nitschinger [ 13/Mar/13 ] |
|
Hi, yes you could try that.. I ran the test suite with 4.2.3 which is the latest one and there were no errors, so our code should work with it. You need to exchange the httpcore and httpcore-nio with the latest 4.2.3 jars I don't think this is 100% the issue, but it helps us get rid of one more factor! Thanks! Michael |
| Comment by Michael Nitschinger [ 13/Mar/13 ] |
|
Okay, the 5 second period can come from this: HttpParams params = new SyncBasicHttpParams(); params.setIntParameter(CoreConnectionPNames.SO_TIMEOUT, 5000) .setIntParameter(CoreConnectionPNames.CONNECTION_TIMEOUT, 5000) .... SO_TIMEOUT is: Defines the socket timeout (SO_TIMEOUT) in milliseconds, which is the timeout for waiting for data or, put differently, a maximum period inactivity between two consecutive data packets). and CONNECTION_TIMEOUT is: Determines the timeout in milliseconds until a connection is established. Dragos, can it be the case that it takes more than 5 seconds to return a result when using curl or so? That would explain the "fail fast" timeout here.. not saying that these times are okay this way, just to find the root cause.. Thanks! |
| Comment by dragos [ 13/Mar/13 ] |
|
Hi Michael, I've made a test with httpcore-nio-4.2.jar and with httpcore-4.2.1.jar and your intuition is good. The httpcore is not the problem because the timeout is still there. With curl the results is back fast, in less then half a second. So the problem must be somewhere in the java SDK in the way the view is retrieved. |
| Comment by dragos [ 13/Mar/13 ] |
| I've moved the Couchbase server to the same machine as the client to have all in same environment for testing. Now all is working fine but it is not possible for our product to stay on the same machine as Couchbase server for obvious reasons. In production we will have more then one app machine which we will try to access the Couchbase cluster. |
| Comment by Michael Nitschinger [ 13/Mar/13 ] |
|
Hi Dragos, okay so its definitely something with those timeouts.. The thing is we can increase them for sure, but the question is if it would work for your application given the long network latency - and if your application stays performant that way. When you're running curl on a request, how long does it take? |
| Comment by dragos [ 14/Mar/13 ] |
|
The curl request is very fast (a few milliseconds, and less then 0.5 seconds i am sure) and the network latency it is not a problem. Some how the couchbase client is taking to much time connecting. When it need to connect to a network machine in the same lan it takes more then 10 seconds. I experimented this in EC2 environment and on my local machine with a VM. If couchbase is local with the test app, the couchbase client is connecting fast. Do you have any points on how a connection should be setup for couchbase client ? I am trying to use the factory builder and the connection factory from java sdk but still with no success. |
| Comment by Tim Smith [ 14/Mar/13 ] |
|
Dragos, I can think of two separate things to try. One is to increase the SO_TIMEOUT to 8000, CONNECTION_TIMEOUT to 12000. Identify what's being hit. Probably more effective would be to use Wireshark to capture all traffic on the client machine, and see what is really happening. Start the capture (with tshark command-line tool, for example), then run the test client, let it time out, then run the curl command, let it succeed, then stop the capture. Gzip the capture data and attach it to this issue. Tim |
| Comment by dragos [ 14/Mar/13 ] |
|
Hi Tim, I've started some load tests to be able to evaluate Couchbase, so this means i moved Couchbase server on the same machine as the load test client. I tried to use a pool of couchbase clients always connected to the server, and after a while the test failed because couldn't create more connections. From my initial research i seen that couchbase client is managing his own connection can you tell me how this is done or what are the policies of shutting down connections ? Can you point me to some best practices for couchbase client connectivity ? |
| Comment by Tim Smith [ 14/Mar/13 ] |
|
I will handle that question about connection pooling, etc., separately, since it is unrelated to this bug about timeouts. On this specific bug report, the current state as I understand it is that: curl returns very quickly with the correct results. The Java client times out after 5 seconds without returning the results. My suggestion is to set up a very simple Java client that performs a single view query, and to get a packet capture of both curl and the Java client, to identify what the two are doing differently and why the curl succeeds but the Java client fails. |
| Comment by Jahangir Zinedine [ 27/Mar/13 ] |
|
Hi Michael, Any update on this issue? I faced the same issue and here is my environment: JRuby 1.7.3 Oracle JDK 1.7(with 1.6 the same thing happened) Couchbase 2.0.1 Java SDK 1.1.3(with 1.1.4 the same thing happened) And latest netty and http-core and other jar files. Appreciate your help. Thanks, Jani |
| Comment by dragos [ 01/Apr/13 ] |
|
Hi All, Finally after a long time i found the workaround needed for the java client to not timeout. As has been suggested by the Couchbase team to use a host name for the Couchabase server i applied the same fix but to the client machine. Meaning on the client machine were the java Couchbase client was timing out ( in Amazon VPC ) we added a hostname for the Couchbase server. Our test URI from http://10.0.7.164:8091/pools has become http://couchbase:8091/pools. This workaround is also fixing a 10 seconds connectivity for the client. On Ubuntu the hostname file is at: /etc/hosts On Windows 7 the hostname file is at: C:\Windows\system32\drivers\etc\hosts Example of host name entry in client machine: 10.0.7.146 couchbase |
| Comment by Michael Nitschinger [ 02/Apr/13 ] |
|
Thanks very much dragos for tracking this down! Does this mean that in your environment after the change, you're not seeing any performance impact anymore? Everything works as expected and performant? Thanks! |
| Comment by dragos [ 02/Apr/13 ] |
|
Hi Michael, In this moment the client does not time out and the time taken by java couchbase client to connect takes around 1.5 seconds from 10 seconds which we can consider a normal behavior. As for performance with this workaround we can continue the POC and evaluate the performance. As a first impression i can say that we see a good speed but i will keep my reservation until final POC is tested and we can achieve a full load test. What i want to emphasize that this is a welcomed workaround but it is not a solution on a longer term for our cloud production site. In a scenario where we need to create new machines and maybe new couchbase clusters it involves manual or specific automatic changes to the hosts file and of course extra managing of this. Bottom line is that we are waiting the fix on the couchbase java sdk 1.1.5 which will make this workaround obsolete. Also i feel the need to mention that this workaround was found in collaboration with the Couchbase team which provided the basic information for the workaround to be found, so thank you guys. |
| Comment by Michael Nitschinger [ 02/Apr/13 ] |
|
Hi Dragos, I'm not sure if there is a thing that we can fix inside the client when this is a DNS/hostname resolution issue with the OS and amazon? We would definitely need to investigate further, but all that the client does is try to use the hostname/IP provided during bootstrap. If nothing comes back or the host can't be found, we can't do much about it. Anyway, I think we need to do some more investigation here to really see whats the problem. |