How to diagnose spymemcached client issues with membase server?
After reading about the (beta) vBucket support in spymemcached, I have attempted to get a complete client/server set-up up and running. Unfortunately, without any success so far. I'm really puzzled about the problems I have encountered and would like to learn how to diagnose the issues I'm currently experiencing.
(@see http://techzone.couchbase.com/wiki/display/membase/prerelease+spymemcach...)
I'm using the binaries for 2.6rc1-36-g1a1deb9 (attached to the techzone page) with membase-server-community_x86_1.6.5.deb deployed on Ubuntu 10.04.2 LTS.
I have two servers running a cluster and 4 buckets, two of each type, standard and dedicated: 'membase-standard', 'membase-dedicated', 'memcached-standard' and 'memcached-dedicated'.
For now, it's stacktraces all the way for all the client set-ups I've tried to test so far.
With authentication I get a 500 failure doing the read of /pools.
Mar 30, 2011 5:17:23 PM net.spy.memcached.vbucket.ConfigurationProviderHTTP readPools WARNING: Connection problems with URI <a href="http://myhost:8091/pools" title="http://myhost:8091/pools">http://myhost:8091/pools</a> ...skipping java.io.IOException: Server returned HTTP response code: 500 for URL: <a href="http://myhost:8091/pools<br /> " title="http://myhost:8091/pools<br /> ">http://myhost:8091/pools<br /> </a> at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1436) at net.spy.memcached.vbucket.ConfigurationProviderHTTP.readToString(ConfigurationProviderHTTP.java:245) at net.spy.memcached.vbucket.ConfigurationProviderHTTP.readPools(ConfigurationProviderHTTP.java:100) at net.spy.memcached.vbucket.ConfigurationProviderHTTP.getBucketConfiguration(ConfigurationProviderHTTP.java:90) at net.spy.memcached.MemcachedClient.<init>(MemcachedClient.java:288) at com.sony.memcached.client.internal.Activator.start(Activator.java:34) at org.eclipse.osgi.framework.internal.core.BundleContextImpl$1.run(BundleContextImpl.java:783) at java.security.AccessController.doPrivileged(Native Method) at org.eclipse.osgi.framework.internal.core.BundleContextImpl.startActivator(BundleContextImpl.java:774) at org.eclipse.osgi.framework.internal.core.BundleContextImpl.start(BundleContextImpl.java:755) at org.eclipse.osgi.framework.internal.core.BundleHost.startWorker(BundleHost.java:370) at org.eclipse.osgi.framework.internal.core.AbstractBundle.resume(AbstractBundle.java:374) at org.eclipse.osgi.framework.internal.core.Framework.resumeBundle(Framework.java:1067) at org.eclipse.osgi.framework.internal.core.StartLevelManager.resumeBundles(StartLevelManager.java:561) at org.eclipse.osgi.framework.internal.core.StartLevelManager.resumeBundles(StartLevelManager.java:546) at org.eclipse.osgi.framework.internal.core.StartLevelManager.incFWSL(StartLevelManager.java:459) at org.eclipse.osgi.framework.internal.core.StartLevelManager.doSetStartLevel(StartLevelManager.java:243) at org.eclipse.osgi.framework.internal.core.StartLevelManager.dispatchEvent(StartLevelManager.java:440) at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:227) at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:337) javax.naming.ConfigurationException: Configuration for bucket memcached-standard was not found. at net.spy.memcached.vbucket.ConfigurationProviderHTTP.readPools(ConfigurationProviderHTTP.java:145) at net.spy.memcached.vbucket.ConfigurationProviderHTTP.getBucketConfiguration(ConfigurationProviderHTTP.java:90) at net.spy.memcached.MemcachedClient.<init>(MemcachedClient.java:288)
Without authentication, the connection is unstable.
2011-03-30 16:58:16.545 INFO net.spy.memcached.MemcachedConnection: Added {QA sa=/192.168.106.130:11210, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0} to connect queue
2011-03-30 16:58:16.554 INFO net.spy.memcached.MemcachedConnection: Added {QA sa=/192.168.106.170:11210, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0} to connect queue
2011-03-30 16:58:16.738 INFO net.spy.memcached.MemcachedConnection: Connection state changed for sun.nio.ch.SelectionKeyImpl@ba5c7a
2011-03-30 16:58:16.739 INFO net.spy.memcached.MemcachedConnection: Connection state changed for sun.nio.ch.SelectionKeyImpl@9446e4
2011-03-30 16:58:16.741 INFO net.spy.memcached.MemcachedConnection: Reconnecting due to exception on {QA sa=192.168.106.170/192.168.106.170:11210, #Rops=1, #Wops=0, #iq=1, topRop=net.spy.memcached.protocol.binary.StoreOperationImpl@14df764, topWop=null, toWrite=0, interested=1}
java.io.IOException: Disconnected unexpected, will reconnect.
at net.spy.memcached.MemcachedConnection.handleReads(MemcachedConnection.java:484)
at net.spy.memcached.MemcachedConnection.handleIO(MemcachedConnection.java:425)
at net.spy.memcached.MemcachedConnection.handleIO(MemcachedConnection.java:278)
at net.spy.memcached.MemcachedClient.run(MemcachedClient.java:1792)
2011-03-30 16:58:16.742 WARN net.spy.memcached.MemcachedConnection: Closing, and reopening {QA sa=192.168.106.170/192.168.106.170:11210, #Rops=1, #Wops=0, #iq=1, topRop=net.spy.memcached.protocol.binary.StoreOperationImpl@14df764, topWop=null, toWrite=0, interested=1}, attempt 0.
2011-03-30 16:58:16.743 WARN net.spy.memcached.protocol.binary.BinaryMemcachedNodeImpl: Discarding partially completed op: net.spy.memcached.protocol.binary.StoreOperationImpl@14df764
2011-03-30 16:58:18.747 INFO net.spy.memcached.MemcachedConnection: Reconnecting {QA sa=192.168.106.170/192.168.106.170:11210, #Rops=0, #Wops=1, #iq=0, topRop=null, topWop=net.spy.memcached.protocol.binary.GetOperationImpl@1ed1b0b, toWrite=0, interested=0}
2011-03-30 16:58:18.748 INFO net.spy.memcached.MemcachedConnection: Connection state changed for sun.nio.ch.SelectionKeyImpl@18a8ce2
2011-03-30 16:58:18.749 INFO net.spy.memcached.MemcachedConnection: Reconnecting due to exception on {QA sa=192.168.106.170/192.168.106.170:11210, #Rops=1, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.GetOperationImpl@1ed1b0b, topWop=null, toWrite=0, interested=1}
java.io.IOException: Disconnected unexpected, will reconnect.
at net.spy.memcached.MemcachedConnection.handleReads(MemcachedConnection.java:484)
at net.spy.memcached.MemcachedConnection.handleIO(MemcachedConnection.java:425)
at net.spy.memcached.MemcachedConnection.handleIO(MemcachedConnection.java:278)
at net.spy.memcached.MemcachedClient.run(MemcachedClient.java:1792)
2011-03-30 16:58:18.750 WARN net.spy.memcached.MemcachedConnection: Closing, and reopening {QA sa=192.168.106.170/192.168.106.170:11210, #Rops=1, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.GetOperationImpl@1ed1b0b, topWop=null, toWrite=0, interested=1}, attempt 0.
2011-03-30 16:58:18.750 WARN net.spy.memcached.protocol.binary.BinaryMemcachedNodeImpl: Discarding partially completed op: net.spy.memcached.protocol.binary.GetOperationImpl@1ed1b0b
java.lang.RuntimeException: Exception waiting for value
at net.spy.memcached.MemcachedClient.get(MemcachedClient.java:1093)
at net.spy.memcached.MemcachedClient.get(MemcachedClient.java:1110)
(my code)
Caused by: java.util.concurrent.ExecutionException: java.lang.RuntimeException: Cancelled
at net.spy.memcached.internal.OperationFuture.get(OperationFuture.java:75)
at net.spy.memcached.internal.GetFuture.get(GetFuture.java:37)
at net.spy.memcached.MemcachedClient.get(MemcachedClient.java:1088)
... 16 more
Caused by: java.lang.RuntimeException: Cancelled
... 19 more
2011-03-30 16:58:20.751 INFO net.spy.memcached.MemcachedConnection: Reconnecting {QA sa=192.168.106.170/192.168.106.170:11210, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0}
2011-03-30 16:58:20.752 INFO net.spy.memcached.MemcachedConnection: Connection state changed for sun.nio.ch.SelectionKeyImpl@23f1bbI've tried connecting to the buckets directly (InetSocketAddress) and that works.
I'm really puzzled about what the problem could be here, as others (@see techzone link above) appear to have a different mileage on this one.
Your feedback would be appreciated.
Hi Matt,
Using a browser or by invoking curl at the command line, accessing the REST interface always works.
Only when I use the spymemcached client, the server fails with a 500 on the /pools URL. The odd thing is that the actual failure is reported in the Java library class responsible for doing the HTTP read, not in the spymemcached code.
From the log:
Server error during processing: ["web request failed",
{path,"/pools"},
{type,error},
{what,function_clause},
{trace,
[{base64,decode,
["Wb",
[86,214,54,22,54,134,86,66,215,55,70,22,
230,70,23,38,67,167,54,86,55,38,87,64]]},
{menelaus_auth,extract_auth,1},
{menelaus_auth,apply_auth_bucket,3},
{menelaus_web,loop,3},
{mochiweb_http,headers,5},
{proc_lib,init_p_do_apply,3}]}]In the case where authentication is required, the server-side log suggests something goes wrong decoding base64 content, which one might expect in an HTTP Authentication header. The server throws an error processing the HTTP request, which then shows up at the client-side through the HttpURLConnection.
Your JSON reply is identical, except your server implementation is '1.6.5.2', mine is '1.6.5' (same step-up for menelaus and ns_server).
There are no logs for the other case, without authentication, where the connection is unstable.
Perhaps I should upgrade to a different membase-server version? An enterprise edition?
Okay, we may be on to something. The client does it's own base64 encoding of the header, using Apache commons codec.
What does your call to the constructor for MemcachedClient look like? Is it the default bucket, or another bucket you're trying to get to? It looks like the server has a problem with the encoding of the HTTP basic auth.
Can you add the -u to your curl invocation? Let's see if it does approximately the same thing? It may be worth grabbing a packet capture from both curl and spy so we can see what's happening with the header.
I start the client with the following code:
ArrayList baseURIs = new ArrayList();
baseURIs.add(new URI("http://myhost:8091/pools"));
baseURIs.add(new URI("http://myOtherhost:8091/pools"));
client = new MemcachedClient(baseURIs, "membase-standard", "membase-standard", "password");(It also fails for 'memcached-standard', the other bucket type with authentication enabled)
I will invoke curl -u next, and I'll modify the source code to use another Base64 encoder. Please stand by.
Interesting. I wonder if the - is throwing things off. The other character that could (but shouldn't) be a problem is a ":"?
I used Apache commons codecs specifically to avoid possible implementation details with writing my own base64 encoder, but perhaps there is more to it.
Hi Matt,
Invoking curl -u with the proper credentials (always) works.
Back to the Java client: I did throw out commons-codec completely and introduced another Base64 encoder. It appears to work, now. I refactored that part of the code into:
protected static String buildAuthHeaderValue(String username, char[] password) {
StringBuilder result = new StringBuilder("Basic ");
StringBuilder basicCredentials = new StringBuilder(username);
basicCredentials.append(':');
if (password != null) {
basicCredentials.append(password);
}
byte[] source = basicCredentials.toString().getBytes();
result.append(Base64.encodeBytes(source));
return result.toString();
}The Base64 encoder I used came from http://www.iharder.net/current/java/base64/, it's completely free and I put it in the net.spy.memcached.util package.
If possible, I'd like to continue our conversation on implementation details on another channel! ;)
So, in the end, it would appear the b̶u̶t̶l̶e̶r̶ client did it, after all.
No problem continuing the conversation. I can be found in the #membase or #couchbase IRC channels pretty regularly as "ingenthr", or you can send an email to matt at couchbase.
I filed an issue: http://techzone.couchbase.com/issues/browse/MB-3563
I am having this exact same problem.
Would appreciate your help solving it ASAP. (Not sure how to implement your solution with that base64.java package)
Thanks,
Dan G.
Hi Danny,
The fix is that I need to replace the base64 encoder, something I can possibly do by Monday.
That said, we'd want to ensure that's the problem. Please verify that you're using the constructor with the bucket name as the username and the password you've put in for the bucket if you can. It'd also be good if you can verify the username/password works with curl to just auth to the system.
The reason I bring up verifying auth is that I've seen a few places where people try to use the Administrator username/password, which then works for the REST interface but is not valid for SASL auth for the bucket.
Hope that helps,
Matt
Hi Dan,
Any error 500 from /pools would indicate something is wrong at the server side.
There are a couple things you can do. One is look in the logs on the server side. Do you see anything that correlates to that error 500? The second thing is to try the /pools URI from another client to see if it has what you expect.
If you're on a platform with curl, or you have something like the firefox "poster" extension, check out the /pools URI from the same place you're running your client.
For instance, here I'm looking at a 1.6.5 system and formatting it with python:
$ curl http://10.1.5.122:8091/pools | python -mjson.tool
% Total % Received % Xferd Average Speed Time Time Time Current
Dload Upload Total Spent Left Speed
100 300 100 300 0 0 2165 0 --:--:-- --:--:-- --:--:-- 2857
{
"componentsVersion": {
"kernel": "2.13.4",
"menelaus": "1.6.5.2",
"mnesia": "4.4.12",
"ns_server": "1.6.5.2",
"os_mon": "2.2.4",
"sasl": "2.1.8",
"stdlib": "1.16.4"
},
"implementationVersion": "1.6.5.2",
"isAdminCreds": false,
"pools": [
{
"name": "default",
"streamingUri": "/poolsStreaming/default",
"uri": "/pools/default"
}
]
}