[JCBC-151] Client does timeout on connect in specific java environments (was believed to be java7 related). Created: 21/Nov/12  Updated: 21/Jul/14  Resolved: 31/Dec/13

Status: Resolved
Project: Couchbase Java Client
Component/s: Core
Affects Version/s: 1.1-dp4
Fix Version/s: 1.3.0
Security Level: Public

Type: Bug Priority: Critical
Reporter: Michael Nitschinger Assignee: Michael Nitschinger
Resolution: Fixed Votes: 3
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Relates to
relates to JCBC-388 Refactor View Connection Management Resolved

 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 (Inactive) [ 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 (Inactive) [ 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.
Comment by aboyev [ 09/Sep/13 ]
Hello, Michael!
I have the same problem. Here is my setup:
- Couchbase 2.1.1
- Java SDK 1.1.9
- Java 1.6.0_27 (and also tried 1.7)
[ERROR] getView | Exception while doing getView: Timed out waiting for operation
[ERROR] Exception while doing getView: I/O reactor has been shut down
It surely has something to do with the client, because when I launch second client it works properly for a while.
Also, it seems to happen under high loads more frequently
Comment by gaurang jhawar [ 24/Oct/13 ]
How did u change the "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." in AWS .. I have EC2 instance for which i want to set the hostname and connect through it like you did... Can you tell me the exact steps for that
Comment by Michael Nitschinger [ 25/Oct/13 ]
Hi Gaurang,

are you also exhibiting a delay on connect? Or during operations? I think these two may be related but should be looked at separately and defined. What environment, client, workload and so on are you running?
Comment by gaurang jhawar [ 25/Oct/13 ]
My env is JDK 1.7.0_09
Client is my local machine ...

Couchbase server installed on aws ..

Reconnecting due to failure to connect to {QA sa=172.31.9.124/172.31.9.124:11210, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0}
java.net.ConnectException: Connection timed out: no further information
at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:692)
at net.spy.memcached.MemcachedConnection.handleIO(MemcachedConnection.java:423)
at net.spy.memcached.MemcachedConnection.handleIO(MemcachedConnection.java:261)
at com.couchbase.client.CouchbaseConnection.run(CouchbaseConnection.java:288)
2013-10-24 22:14:01.893 WARN com.couchbase.client.CouchbaseConnection: Closing, and reopening {QA sa=172.31.9.124/172.31.9.124:11210, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0}, attempt 1.
2013-10-24 22:14:05.903 INFO com.couchbase.client.CouchbaseConnection: Reconnecting {QA sa=172.31.9.124/172.31.9.124:11210, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0}
2013-10-24 22:14:09.632 INFO com.couchbase.client.ViewConnection: Added 172.31.9.124 to connect queue
Comment by Michael Nitschinger [ 25/Oct/13 ]
One thing to note here is that this is not a good idea. You have "the internet" between your computer (client) and the server which adds latency. Can you try running the application also in an AWS instance and see if the error goes away?
Comment by gaurang jhawar [ 25/Oct/13 ]
I gave the elastic amazon IP in the url and also tried what dragos tried but that also didn`t work for me .. I made ALL TCP ports on firewall ON ... And I am not sure why it reconnects to the IP or fails to connect and load data in the bucket.

But its the same case as dragos ... for production that`s not viable .. since not everything can be on AWS.

Also I can connect to the same instance via telnet and http(browser) .. I don`t know why I am facing this issue with Java 1.7.

"2013-10-24 22:14:01.893 WARN com.couchbase.client.CouchbaseConnection: Closing, and reopening {QA sa=172.31.9.124/172.31.9.124:11210, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0}, attempt 1.
2013-10-24 22:14:05.903 INFO com.couchbase.client.CouchbaseConnection: Reconnecting {QA sa=172.31.9.124/172.31.9.124:11210, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0}
2013-10-24 22:14:09.632 INFO com.couchbase.client.ViewConnection: Added 172.31.9.124 to connect queue
2013-10-24 22:14:09.632 INFO com.couchbase.client.CouchbaseClient: viewmode property isn't defined. Setting viewmode to production mode
in INIT **************.
Here is the entity set : users
2013-10-24 22:14:09.868 WARN com.couchbase.client.CouchbaseConnection: Node expected to receive data is inactive. This could be due to a failure within the cluster. Will check for updated configuration. Key without a configured node is: 0.
30 Seconds: Load is in progress
2013-10-24 22:14:09.993 INFO com.couchbase.client.CouchbaseConnection: Added {QA sa=/172.31.9.124:11210, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0} to connect queue
2013-10-24 22:14:12.037 INFO com.couchbase.client.CouchbaseConnection: Connection state changed for sun.nio.ch.SelectionKeyImpl@6dae04e2
2013-10-24 22:14:12.037 INFO com.couchbase.client.CouchbaseConnection: Reconnecting due to failure to connect to {QA sa=172.31.9.124/172.31.9.124:11210, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0}
java.net.ConnectException: Connection timed out: no further information"

NOTE here it tried to reconnect to the client and says its inactive and I am not sure if this is a firewall issue or something else.
Comment by Michael Nitschinger [ 25/Oct/13 ]
Can you provide debug log information for the connect process? Maybe this helps pinning down where the issue is. (you can read here how to do it if you don't know already) :http://nitschinger.at/Logging-with-the-Couchbase-Java-Client

thanks
Comment by gaurang jhawar [ 25/Oct/13 ]
http://s000.tinyupload.com/index.php?file_id=46832814372422198765
Comment by Michael Nitschinger [ 25/Oct/13 ]
Thanks, can you also share the code you use?

In the code it looks like you are creating the CouchbaseClient object twice.
Please note that the bootstrapping succeeds (!) it is different from the ticket reported here.

Are you sure port 11210 is open from client to server? It looks like something is blocking it, http seems to work fine.
Comment by gaurang jhawar [ 25/Oct/13 ]
http://s000.tinyupload.com/index.php?file_id=34200463437173886967



ya the port is opened.

http://s000.tinyupload.com/index.php?file_id=06508245784961590671

Both inbound / outbound on aws as well as my local machine firewall ports are open
Comment by gaurang jhawar [ 26/Oct/13 ]
Any updateS?
Comment by couchbase-user [ 27/Oct/13 ]
This is a nightmare, can't believe no solution has been found yet for over a year now.....
Comment by Michael Nitschinger [ 28/Oct/13 ]
Hi couchbase-user, are you also running app/db over the internet or on a specific ec2 environment?
Comment by couchbase-user [ 28/Oct/13 ]
hey, actually I'm running them all on a local small network.
I am using ubuntu 12.4 on all machines and running java application on headnode to get view data and store them locally.
Comment by Michael Nitschinger [ 28/Oct/13 ]
Hm, I wonder why you are hitting this, I'm not sure its related.. do you get the same exception as the top of the ticket here? Can you provide debug logs so we can see at which point it is happening?

Maybe we need to tweak socket timeouts.
Comment by couchbase-user [ 28/Oct/13 ]
hey, here is my execution log:

28-Oct-2013 09:29:09 com.couchbase.client.CouchbaseProperties setPropertyFile
INFO: Could not load properties file "cbclient.properties" because: File not found with system classloader.
2013-10-28 09:29:09.618 INFO com.couchbase.client.CouchbaseConnection: Added {QA sa=/192.168.0.100:11210, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0} to connect queue
2013-10-28 09:29:09.620 INFO com.couchbase.client.CouchbaseConnection: Added {QA sa=/192.168.0.101:11210, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0} to connect queue
2013-10-28 09:29:09.620 INFO com.couchbase.client.CouchbaseConnection: Added {QA sa=/192.168.0.102:11210, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0} to connect queue
2013-10-28 09:29:14.635 INFO com.couchbase.client.CouchbaseConnection: Connection state changed for sun.nio.ch.SelectionKeyImpl@7f09fd93
2013-10-28 09:29:14.635 INFO com.couchbase.client.CouchbaseConnection: Connection state changed for sun.nio.ch.SelectionKeyImpl@79a5f739
2013-10-28 09:29:14.636 INFO com.couchbase.client.CouchbaseConnection: Connection state changed for sun.nio.ch.SelectionKeyImpl@68e6ff0d
2013-10-28 09:29:14.656 INFO com.couchbase.client.ViewConnection: Added Cloud-assistant.local to connect queue
2013-10-28 09:29:19.663 INFO com.couchbase.client.ViewConnection: Added 192.168.0.102 to connect queue
2013-10-28 09:29:19.666 INFO com.couchbase.client.ViewConnection: Added 192.168.0.100 to connect queue
2013-10-28 09:29:19.667 INFO com.couchbase.client.CouchbaseClient: viewmode property isn't defined. Setting viewmode to production mode
2013-10-28 09:29:19.788 INFO com.couchbase.client.http.AsyncConnectionManager: Opening new Couchbase HTTP connection
2013-10-28 09:29:19.794 INFO com.couchbase.client.http.AsyncConnectionManager$ConnRequestCallback: /192.168.0.102:8092 - Session request successful
2013-10-28 09:29:24.815 ERROR com.couchbase.client.ViewNode$EventLogger: Connection timed out: [192.168.0.102/192.168.0.102: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:483)
    at HelloWorld.Export_Couchbase_View(HelloWorld.java:85)
    at HelloWorld.main(HelloWorld.java:287)
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)

I thought this is exactly the same as the error at the top of this thread....
Comment by Michael Nitschinger [ 28/Oct/13 ]
In your logs I can see that 192.168.0.101 is changed to Cloud-assistant.local. Could it be that this is a DNS issue in your environment?
Also please make sure that ports 8091, 8092 (!) and 11210 are reachable on each node.

Both the socket and connection timeout for views are set to 5 second which is already "quite high" if you want to run a real workload over it.
Comment by couchbase-user [ 28/Oct/13 ]
I'm not sure what the DNS has to do with it or how to check it, something to note here is that sometimes it works fine (very rare).
I have also just tried to change the switch but still the same problem.
I'm working on investigating the DNS and firewall issue. thanks
Comment by Michael Nitschinger [ 28/Oct/13 ]
Okay, if you go directly to the view url, how long does it take you to? like with curl... so we can see how far you are over the 5 seconds and if you are under it then there's something else going on.
Comment by couchbase-user [ 28/Oct/13 ]
I have added different servers names to hosts files in all servers and disabled the firewall on all of them and now it seems to work fine.
Thanks a lot for your help Michael.
Comment by Michael Nitschinger [ 28/Oct/13 ]
perfect, good to know it works now.
Comment by gaurang jhawar [ 28/Oct/13 ]
Any updates on my issue Michael Nitschinger. Thanks
Comment by Michael Nitschinger [ 29/Oct/13 ]
Since we fixed the suspected issue with "couchbase-user" in kind of the same way,
ca you first verify that

- All ports are reachable from all the boxes (11210, 8091, 8092)
- DNS settings are configured properly, this is especially important in EC2

If you look through the thread here, some of the people reporting this thing fixed once they made sure their environmental settings were okay. Can you double check?
Comment by gaurang jhawar [ 31/Oct/13 ]
Couchbase-user how did u configure hostname . can u tell me a step by step approach .. dont give me links to couchbase documentation that didn`t help ..

Michael .. the ports are open I am able to ping .. it connects via java and everything but the timeout is quite frequent ..



C:\Users\gaurang\Downloads>tcping 54.219.141.78 8091

Probing 54.219.141.78:8091/tcp - Port is open - time=21.692ms
Probing 54.219.141.78:8091/tcp - Port is open - time=19.357ms
Probing 54.219.141.78:8091/tcp - Port is open - time=15.414ms
Probing 54.219.141.78:8091/tcp - Port is open - time=16.225ms

Ping statistics for 54.219.141.78:8091
     4 probes sent.
     4 successful, 0 failed.
Approximate trip times in milli-seconds:
     Minimum = 15.414ms, Maximum = 21.692ms, Average = 18.172ms

C:\Users\gaurang\Downloads>tcping 54.219.141.78 11210\

Probing 54.219.141.78:11210/tcp - Port is open - time=18.236ms
Probing 54.219.141.78:11210/tcp - Port is open - time=23.513ms
Probing 54.219.141.78:11210/tcp - Port is open - time=1218.881ms
Probing 54.219.141.78:11210/tcp - Port is open - time=14.712ms

Ping statistics for 54.219.141.78:11210
     4 probes sent.
     4 successful, 0 failed.
Approximate trip times in milli-seconds:
     Minimum = 14.712ms, Maximum = 1218.881ms, Average = 318.836ms

Comment by CathodTech [ 13/Dec/13 ]
We have been facing the same issue for couples of months - with Couchbase on RHEL, and we have just found out the solution that works for us.

We have 2 Tomcat nodes running; 1 with Java 1.7 and another with 1.6. Couchbase was deployed on another 4 servers in the same network. We simply defined all Couchbase nodes in /etc/hosts file in both Tomcat nodes as you normally would (with x.x.x.x hostname), then it magically works for us - without having to restart Tomcat, nor Couchbase nodes.
Comment by Michael Nitschinger [ 13/Dec/13 ]
Thanks for pointing this out, I'll see if I can get it into the official docs to aid other people. To me this really looks like java-related and network-related. Interestingly only a few people are hitting it.
Comment by CathodTech [ 14/Dec/13 ]
For the issue I faced, it looks more like Java API related. Perhaps, something to do with DNS (e.g., something like gethostbyname() / gethostbyaddr()), and how the API handles the case when IP has no hostname. Note that we only use IP address to add nodes into Couchbase cluster and Java on other servers also connect to Couchbase with IP address, not hostname.

From the trace, we found that java code has no problem connecting (via connection pool) with Couchbase nodes that has IP/hostname pair in /etc/hosts. But for Couchbase nodes that were not defined in /etc/hosts, it attempted to connect, then the connection dropped, and returned timeout issue.

My team also found that later when he restarted java to re-deploy, Couchbase connection attempts at start-up were much faster (on both Java 1.6 and 1.7).

For this issue, we didn't face it when deploying Java and Couchbase on the same server as, perhaps, it is common to have "127.0.0.1 localhost" defined in /etc/hosts.

We hope that the solution we found would help you and others as well. Not sure if others are facing the same scenario, though.
Comment by David Borsos [ 18/Dec/13 ]
I've ran into a very similar/the same situation with the latest couchbase (2.2.0) server and java client (1.2.3), I thought I share my experiences.

The problem I faced was when trying to call CouchbaseClient.getView(). This apparently goes to one node in the couchbase cluster and queries some view metadata over HTTP (roughly). However I got "ERROR com.couchbase.client.ViewNode$EventLogger: Connection timed out" and that pretty much killed my client there. Seeing the solutions here with the hosts file workaround, I tried that and it indeed worked, but it's not really a suitable solution for us, so I decided to see into this a little bit more. Here is what I found.

(Disclaimer: this worked for me, and although I found other ways around this they may not work for you, and I did these attempting to solve this particular issue and didn't really care about anything else these changes may break, so be careful!)

(0) Baseline, the environment specific thing that actually causes the issue is that call java api call InetAddress.getHostFromNameService(InetAddress addr, boolean check) returns very slowly if there's no hostname to be found for a given IP. I have no idea why is that in my environment, I suppose could be because of a bunch of different reasons. Slow here means that it takes 4-5 secs for me for this call to return with an unknown hostname

This comes into the picture when the couchbase client tries to get a view. It uses Apache Http client to do this, and the following things happen:
(1) When the request for the view gets created, eventually we get to BaseIOReactor.execute which instantiates SessionHandle, and registers the time when this happened (this will cause the timeout)
(2) Somewhere in the request processing, we actually DO hit getHostFromNameService. More specifically this happens because a RequestTargetHost interceptor runs and this injects the "Host" header into the HTTP request.
(3) some time after (2) we hit a timeout check which compares the timestamp recorded in (1) and the current time, obviously resulting in a timeout and the error in the client if (2) takes a long time as indicated

The ideal solution would obviously be to fix whatever is wrong with my DNS configs, but I'm not (yet) sure what's wrong (running Ubuntu 13.10 btw). And also make sure that our live environments won't have the same issue...

One workaround I found that might be generally usable is to override the JVM's DNS resolver, by starting the client with: -Dsun.net.spi.nameservice.provider.1=dns,sun This worked for me, but I don't know what side-effects it may have (generally this may not be a great idea). Additionally this resulted in a significant increase of startup speed as the couchbase client seems to do a lot of ip->hostname lookups when it's starting (are these really necessary?)

Also I'd like to ask from the Couchbase folks if it's really necessary to do this reverse DNS lookup for every HTTP request. I cloned your client from git, and removed the RequestTargetHost interceptor from these calls; that also solved the timeout problem, and all seems to work fine. I didn't do exhaustive testing on it, and this, too, can be environment specific - running my couchbase cluster in local VMs at the moment.

Thanks.
Comment by Michael Nitschinger [ 19/Dec/13 ]
Hi David,

thanks for the heads-up, that gives me a better idea of whats going on. I basically revamped the whole view connection management for the next 1.3 release which hopefully should address this to. Would you want to try it out based on a preliminary build?

The thing is that you can't remove the RequestTargetHost, but it only does the DNS lookup if HTTP.TARGET_HOST is not set, but we can infer that from our configuration. So the new code basically sets it before the request is put in the queue, once we've determined which node to ask, then it should be skipped.

I already have that locally, so if you want to try it out we can quickly see if it fixes the issue.
Comment by Michael Nitschinger [ 19/Dec/13 ]
The issue will be fixed with the overall changeset of jcbc-388, which will appear in - as it stands now - 1.3, slated for jan 2014.
Comment by David Borsos [ 19/Dec/13 ]
Michael,

That sounds great. I'd be happy to help you verify your new code; send it over or let me know how can I get it, I'll switch to it and see if it solves the problem. If we can get the new version in early January (I saw it's scheduled for the 7th) that's cool too, we won't be doing much during the holidays anyway :)

Thanks
Comment by Sergii [ 19/Dec/13 ]
Hi Michael,

i have run into the same issue with couchbase 2.2 on mac - Java 1.7

Can i have the changed jar to try the fix?

Thanks
Comment by Michael Nitschinger [ 31/Dec/13 ]
A fix for this has been merged into master and will be available in the next (1.3.0) release.
Comment by Michael Nitschinger [ 31/Dec/13 ]
The new code minimizes dns lookups to workaround the issue, but the environment still needs to be fixed properly :)
Comment by Oded Hassidi [ 21/Jul/14 ]
Was this fixed, since we are having issues with timeot on Java SDK v1.4.x, and we are using JDK 7?
This is not happen all the time, if I run a thread that runs many request it occur every 2-4 min
Comment by Michael Nitschinger [ 21/Jul/14 ]
This issue happened during startup, are you experiencing issues during startup? Where do you get the timeouts?
Comment by Oded Hassidi [ 21/Jul/14 ]
Thanks for the quick response.
The timeout are not at startup it happens during runtime. every 2-3 minutes I get the followed:

SEVERE: The RuntimeException could not be mapped to a response, re-throwing to the HTTP container
java.lang.RuntimeException: Timed out waiting for operation
at com.couchbase.client.internal.HttpFuture.get(HttpFuture.java:75)
        at com.couchbase.client.CouchbaseClient.query(CouchbaseClient.java:778)
Caused by: java.util.concurrent.TimeoutException: Timed out waiting for operation
at com.couchbase.client.internal.HttpFuture.waitForAndCheckOperation(HttpFuture.java:93)
at com.couchbase.client.internal.ViewFuture.get(ViewFuture.java:65)
at com.couchbase.client.internal.ViewFuture.get(ViewFuture.java:49)
at com.couchbase.client.internal.HttpFuture.get(HttpFuture.java:72)
... 45 more
Generated at Mon Oct 20 08:18:08 CDT 2014 using JIRA 5.2.4#845-sha1:c9f4cc41abe72fb236945343a1f485c2c844dac9.