redis.netty.BulkReply cannot be cast to redis.netty.MultiBulkReply

[s-boyle]

Using netty-client, after many calls to hgetall I start getting ClassCastException. I call hgetall a lot, for the cases that fail I can query the key with redis-cli, it is there an has more than one field of data, should generate a MultiBulkReply. Not clear why I see responses that are not MultiBulkReply.

java.lang.ClassCastException: redis.netty.BulkReply cannot be cast to redis.netty.MultiBulkReply

net.connexity.actor.CCMSTMActor$$anon$1.apply(STMActor.scala:2035)
spullara.util.concurrent.Promise.set(Promise.java:86)
redis.netty.client.RedisClientBase$1.messageReceived(RedisClientBase.java:113)
org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:302)
org.jboss.netty.handler.codec.replay.ReplayingDecoder.unfoldAndFireMessageReceived(ReplayingDecoder.java:525)
org.jboss.netty.handler.codec.replay.ReplayingDecoder.callDecode(ReplayingDecoder.java:506)
org.jboss.netty.handler.codec.replay.ReplayingDecoder.messageReceived(ReplayingDecoder.java:443)
org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:274)
org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:261)
org.jboss.netty.channel.socket.nio.NioWorker.read(NioWorker.java:349)
org.jboss.netty.channel.socket.nio.NioWorker.processSelectedKeys(NioWorker.java:280)
org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:200)
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
java.lang.Thread.run(Thread.java:724)

[spullara]

What version of Redis so I can try and reproduce?

[spullara]

Also, it might help if you printed out what was coming back in the bulkreply.

[s-boyle]

redis 2.6.14.

I'll see about getting the contents of the bulkreply.

[s-boyle]

I'm not sure how to get the BulkReply and print it. I'm either getting the MultiBulkReply or an Exception. The code looks something like this:
val r = redis.netty.client.RedisClient.connect("redis", 6379)

  val scKey = "sc:" + sid.toString + ":" + mid.toString

  val scFuture = r.hgetall(scKey)

  val s = scFuture
    .onSuccess(new Block[MultiBulkReply]() {
       @Override def apply(mbr: MultiBulkReply) {
         logger.info("got mbr data of  " + mbr)
       }
    })
  val fail = scFuture.onFailure(new Block[Throwable]() {
       @Override def apply(thrown: Throwable) {
         logger.error("Error with async redis, message is " + thrown)
       }
    })

I also tried the following and got a propler looking MultiBulkReply:
val f = fail.onSuccess(new BlockMultiBulkReply {
@OverRide def apply(mbr: MultiBulkReply) {
logger.info("mbr is " + mbr)

I also tried putting a breakpoint in RedisBaseClient.java, line 113, per the stack trace. I'm not clear that I found the problem. Everything I saw looked like my data, one piece of it at a time.

I'm calling hgetall about 300k times in about 30 seconds. Is there a limit to the number of outstanding requests?

Any suggestions on how to print out the BulkReply?

[spullara]

I've added better propagation of this error to master if you can download and build. You don't need to do everything, probably just:

CI=1 mvn install -pl :netty-client -am

My current theory is that you are getting an ErrorReply and we are mishandling it.

[s-boyle]

Here is the stack trace I'm getting with your latest changes:
redis.netty.client.RedisException: Incorrect type for 0.0 should be redis.netty.MultiBulkReply but is redis.netty.BulkReply
at redis.netty.client.RedisClientBase$5.set(RedisClientBase.java:202)
at redis.netty.client.RedisClientBase$1.messageReceived(RedisClientBase.java:117)
at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:302)
at org.jboss.netty.handler.codec.replay.ReplayingDecoder.unfoldAndFireMessageReceived(ReplayingDecoder.java:525)
at org.jboss.netty.handler.codec.replay.ReplayingDecoder.callDecode(ReplayingDecoder.java:506)
at org.jboss.netty.handler.codec.replay.ReplayingDecoder.messageReceived(ReplayingDecoder.java:443)
at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:274)
at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:261)
at org.jboss.netty.channel.socket.nio.NioWorker.read(NioWorker.java:349)
at org.jboss.netty.channel.socket.nio.NioWorker.processSelectedKeys(NioWorker.java:280)
at org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:200)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:724)

The data that is displayed in the Errors is parts of the data I'm trying to read. From a redis-cli perspective the data looks like this:
redis redis:6379[1]> hgetall sc:19:215

1. "aCPM"
2. "10.0"
3. "pCPM"
4. "0.0"
5. "I"
6. "0"
7. "sTax"
8. "0.0"
9. "sDet"
10. "0.0"
11. "cEnabled"
12. "false"

In the error shown above, the 0.0 is one of the values for a field in a hash. Other similar errors show field names instead of the value. Seems that sometimes I'm getting each field or value from a hash as individual BulkReply messages instead of everything in a MultiBulkReply.

Seems like your messageReceived method is getting a BulkReply, does not appear that I hit your new case of an ErrorReply.

[spullara]

Do you think you could possibly package up something that reproduces this for me? My current guess is that somewhere we are reading off the wire in the middle of a MultiBulkReply. No idea how that could happen. Is this a highly concurrent workload against a single connection? My current guess based on this new data is that some assumption I am making about Netty is proving to be incorrect.

[spullara]

Ok, I have a trivial reproduction case. I can dig into now.

https://gist.github.com/spullara/5911104

[s-boyle]

If your test doesn't reproduce it then I will write a test but I can't get to it for a while.

I'm using a single thread. I instantiate the client once:
val r = redis.netty.client.RedisClient.connect("redis", 6379)

You should be able to test using the code snippet I sent a couple of days ago in a loop like this:
for (sid <- 1 to 10; mid <- 1 to 10) { }

[spullara]

I think I have fixed the issue you identified. Thanks a ton for finding this and helping figure it out.

[s-boyle]

The fix seems to work for the case described above. I've now created a connection pool of netty-clients using commons-pooling. Now, for each iteration, I get a connection from the pool do a single call and return the connection to the pool - this spreads the commands over more than one netty-client. With the pooling, I'm getting an occasionally mangled MBR.

In the debugger, a typical good MBR looks like this:
{redis.netty.MultiBulkReply@6463}"[aCPM, 11.0, pCPM, 7.15, I, 0, sTax, 0.0, sDet, 0.0, cEnabled, false]"

A mangled MBR looks like this:
{redis.netty.MultiBulkReply@5548}"[$5\r\n, \n*12, aCPM, .5\r\n$4\r\npCPM\r\n#3\r\n,I, 0, sTax, 0.0, sDet, 0.0, cEnabled, false]"

It appears that the response from redis was not parsed properly. Also, looking at the data in redis, I think the mangled responses contain data for a different key in redis than the query was for. Seems again like there is a concurrency issue. Thoughts?

Thanks, I appreciate your help.