search

OpenTSDB / asynchbase

A fully asynchronous, non-blocking, thread-safe, high-performance HBase client.
https://github.com/OpenTSDB/asynchbase
BSD 3-Clause "New" or "Revised" License
609 stars 303 forks source link

Bug when delete followed by put #33

Closed shrijeet closed 12 years ago

shrijeet commented 12 years ago

Client Version: 1.3.1 Server Version: 0.92.1 Hadoop version: cdh3u0

Desciption

A special case when client does a delete for a key followed by put for same key AND it does so for two different tables (which results into MultiAction batch of two delete-put pairs) - the region server detects corruption in RPC sent to it.

How to reproduce

import org.hbase.async.DeleteRequest;
import org.hbase.async.HBaseClient;
import org.hbase.async.PutRequest;

public class PutDeleteBug {

    public static void main(String args[]) throws Exception {
        final HBaseClient client = new HBaseClient("pww-30");

        for (int i = 0; i < 2; i++) {
            PutRequest put;
            if (i % 2 == 0) {
                put = new PutRequest("t1", String.valueOf(i), "f", "q", "v");
            } else {
                put = new PutRequest("t0", String.valueOf(i), "f", "q", "v");
            }
            final DeleteRequest delete = new DeleteRequest(put.table(), put.key());
            client.delete(delete);
            client.put(put);
        }
        client.shutdown().joinUninterruptibly();
    }

}

Logs with details of error

client log:

2012-07-25 11:50:36,378 DEBUG [main] AsyncPutRequestFileWriter: Set file called for /tmp/asyncputs.bin
2012-07-25 11:50:36,383 DEBUG [main] AsyncPutRequestFileWriter: setFile ended
2012-07-25 11:50:36,383 DEBUG [main] AsyncPutRequestFileWriter: Opening AsyncFileWriter.
2012-07-25 11:50:36,410 INFO  [main] ZooKeeper: Client environment:zookeeper.version=3.3.3-1203054, built on 11/17/2011 05:47 GMT
2012-07-25 11:50:36,410 INFO  [main] ZooKeeper: Client environment:host.name=10.241.94.172
2012-07-25 11:50:36,410 INFO  [main] ZooKeeper: Client environment:java.version=1.6.0_32
2012-07-25 11:50:36,410 INFO  [main] ZooKeeper: Client environment:java.vendor=Apple Inc.
2012-07-25 11:50:36,410 INFO  [main] ZooKeeper: Client environment:java.home=/Library/Java/JavaVirtualMachines/1.6.0_32-b05-420.jdk/Contents/Home
2012-07-25 11:50:36,410 INFO  [main] ZooKeeper: Client environment:java.class.path=/Users/shrijeet/Documents/workspace/asynchbase.experiments/bin:/Users/shrijeet/git_ws/grid/thirdparty/asynchbase/target/classes:/Users/shrijeet/.m2/repository/com/google/guava/guava/12.0/guava-12.0.jar:/Users/shrijeet/.m2/repository/com/google/code/findbugs/jsr305/1.3.9/jsr305-1.3.9.jar:/Users/shrijeet/.m2/repository/io/netty/netty/3.5.1.Final/netty-3.5.1.Final.jar:/Users/shrijeet/.m2/repository/com/stumbleupon/async/1.2.0/async-1.2.0.jar:/Users/shrijeet/.m2/repository/org/slf4j/slf4j-api/1.6.4/slf4j-api-1.6.4.jar:/Users/shrijeet/.m2/repository/org/apache/zookeeper/zookeeper/3.3.4/zookeeper-3.3.4.jar:/Users/shrijeet/.m2/repository/org/slf4j/log4j-over-slf4j/1.6.4/log4j-over-slf4j-1.6.4.jar:/Users/shrijeet/.m2/repository/org/slf4j/jcl-over-slf4j/1.6.4/jcl-over-slf4j-1.6.4.jar:/Users/shrijeet/.m2/repository/junit/junit/4.10/junit-4.10.jar:/Users/shrijeet/.m2/repository/org/hamcrest/hamcrest-core/1.1/hamcrest-core-1.1.jar:/Users/shrijeet/.m2/repository/org/javassist/javassist/3.15.0-GA/javassist-3.15.0-GA.jar:/Users/shrijeet/.m2/repository/org/mockito/mockito-all/1.9.0/mockito-all-1.9.0.jar:/Users/shrijeet/.m2/repository/org/powermock/powermock-module-junit4/1.4.10/powermock-module-junit4-1.4.10.jar:/Users/shrijeet/.m2/repository/org/powermock/powermock-module-junit4-common/1.4.10/powermock-module-junit4-common-1.4.10.jar:/Users/shrijeet/.m2/repository/org/powermock/powermock-core/1.4.10/powermock-core-1.4.10.jar:/Users/shrijeet/.m2/repository/org/powermock/powermock-reflect/1.4.10/powermock-reflect-1.4.10.jar:/Users/shrijeet/.m2/repository/org/objenesis/objenesis/1.2/objenesis-1.2.jar:/Users/shrijeet/.m2/repository/org/powermock/powermock-api-mockito/1.4.10/powermock-api-mockito-1.4.10.jar:/Users/shrijeet/.m2/repository/org/powermock/powermock-api-support/1.4.10/powermock-api-support-1.4.10.jar:/Users/shrijeet/github/opentsdb/third_party/logback/logback-classic-0.9.24.jar:/Users/shrijeet/github/opentsdb/third_party/logback/logback-core-0.9.24.jar:/Users/shrijeet/github/opentsdb/third_party/suasync/suasync-1.1.0.jar:/Users/shrijeet/github/opentsdb/third_party/netty/netty-3.2.3.Final.jar:/Users/shrijeet/github/opentsdb/third_party/slf4j/slf4j-api-1.6.1.jar
2012-07-25 11:50:36,411 INFO  [main] ZooKeeper: Client environment:java.library.path=.:/Library/Java/Extensions:/System/Library/Java/Extensions:/usr/lib/java
2012-07-25 11:50:36,411 INFO  [main] ZooKeeper: Client environment:java.io.tmpdir=/var/folders/zw/qjtv8ln55pl13s1txf6241z80000gp/T/
2012-07-25 11:50:36,411 INFO  [main] ZooKeeper: Client environment:java.compiler=<NA>
2012-07-25 11:50:36,411 INFO  [main] ZooKeeper: Client environment:os.name=Mac OS X
2012-07-25 11:50:36,411 INFO  [main] ZooKeeper: Client environment:os.arch=x86_64
2012-07-25 11:50:36,411 INFO  [main] ZooKeeper: Client environment:os.version=10.7.4
2012-07-25 11:50:36,411 INFO  [main] ZooKeeper: Client environment:user.name=shrijeet
2012-07-25 11:50:36,411 INFO  [main] ZooKeeper: Client environment:user.home=/Users/shrijeet
2012-07-25 11:50:36,411 INFO  [main] ZooKeeper: Client environment:user.dir=/Users/shrijeet/Documents/workspace/asynchbase.experiments
2012-07-25 11:50:36,412 INFO  [main] ZooKeeper: Initiating client connection, connectString=pww-30 sessionTimeout=5000 watcher=org.hbase.async.HBaseClient$ZKClient@36f0b7f8
2012-07-25 11:50:36,414 DEBUG [main] ClientCnxn: zookeeper.disableAutoWatchReset is false
2012-07-25 11:50:36,429 INFO  [main] HBaseClient: Need to find the -ROOT- region
2012-07-25 11:50:36,429 INFO  [main-SendThread()] ClientCnxn: Opening socket connection to server pww-30/172.22.0.30:2181
2012-07-25 11:50:36,430 DEBUG [main] AsyncPutRequestFileWriter: Stopping AsyncFileWriter from mail thread.
2012-07-25 11:50:36,430 DEBUG [main] AsyncPutRequestFileWriter: Waiting for writer thread to join.
2012-07-25 11:50:36,430 DEBUG [AsyncWriter Thread] AsyncPutRequestFileWriter: Writer thread interrupted, exiting loop.
2012-07-25 11:50:36,430 INFO  [AsyncWriter Thread] AsyncPutRequestFileWriter: Writer has been stopped, flushing all pending items in queue before exiting, items to flush: 0
2012-07-25 11:50:36,431 DEBUG [AsyncWriter Thread] AsyncPutRequestFileWriter: Closing file /tmp/asyncputs.bin
2012-07-25 11:50:36,431 INFO  [main] AsyncPutRequestFileWriter: Total events saved in lifetime : 0
2012-07-25 11:50:36,461 INFO  [main-SendThread(pww-30:2181)] ClientCnxn: Socket connection established to pww-30/172.22.0.30:2181, initiating session
2012-07-25 11:50:36,463 DEBUG [main-SendThread(pww-30:2181)] ClientCnxn: Session establishment request sent on pww-30/172.22.0.30:2181
2012-07-25 11:50:36,491 INFO  [main-SendThread(pww-30:2181)] ClientCnxn: Session establishment complete on server pww-30/172.22.0.30:2181, sessionid = 0x135ca75f41b6469, negotiated timeout = 12000
2012-07-25 11:50:36,492 DEBUG [main-EventThread] HBaseClient: Got ZooKeeper event: WatchedEvent state:SyncConnected type:None path:null
2012-07-25 11:50:36,494 DEBUG [main-EventThread] HBaseClient: Finding the -ROOT- region in ZooKeeper
2012-07-25 11:50:36,498 DEBUG [main-EventThread] HBaseClient: Done handling ZooKeeper event: WatchedEvent state:SyncConnected type:None path:null
2012-07-25 11:50:36,524 DEBUG [main-SendThread(pww-30:2181)] ClientCnxn: Reading reply sessionid:0x135ca75f41b6469, packet:: clientPath:/hbase/root-region-server serverPath:/hbase/root-region-server finished:false header:: 1,4  replyHeader:: 1,-1,0  request:: '/hbase/root-region-server,T  response:: #ffffffff000193138323837407077772d33312e72666973657276652e6e65747077772d33312e72666973657276652e6e65742c36303032302c31333433313733333537333532,s{25784830233,25784830233,1343173363725,1343173363725,0,0,0,0,69,0,25784830233} 
2012-07-25 11:50:36,528 INFO  [main-EventThread] HBaseClient: Connecting to -ROOT- region @ 172.22.0.31:60020
2012-07-25 11:50:36,555 DEBUG [main-EventThread] RegionClient: [id: 0x6ab30913] OPEN
2012-07-25 11:50:36,562 DEBUG [main-EventThread] RegionClient: RPC queued: HBaseRpc(method="getClosestRowBefore", table="-ROOT-", key=".META.,t1,0,:,:", region=RegionInfo(table="-ROOT-", region_name="-ROOT-,,0", stop_key=""), attempt=0)
2012-07-25 11:50:36,563 DEBUG [main-EventThread] Deferred: callback=retry RPC@121398849 returned Deferred@240990493(state=PENDING, result=null, callback=type getClosestRowBefore response -> locateRegion in ROOT -> passthrough -> retry RPC -> (continuation of Deferred@173057609 after retry RPC@121398849), errback=passthrough -> passthrough -> locateRegion errback -> retry RPC -> (continuation of Deferred@173057609 after retry RPC@121398849)), so the following Deferred is getting paused: Deferred@173057609(state=PAUSED, result=Deferred@240990493, callback=<none>, errback=<none>)
2012-07-25 11:50:36,563 DEBUG [main-EventThread] RegionClient: RPC queued: HBaseRpc(method="getClosestRowBefore", table="-ROOT-", key=".META.,t1,0,:,:", region=RegionInfo(table="-ROOT-", region_name="-ROOT-,,0", stop_key=""), attempt=0)
2012-07-25 11:50:36,563 DEBUG [main-EventThread] Deferred: callback=retry RPC@886376425 returned Deferred@234515736(state=PENDING, result=null, callback=type getClosestRowBefore response -> locateRegion in ROOT -> passthrough -> retry RPC -> (continuation of Deferred@873482707 after retry RPC@886376425), errback=passthrough -> passthrough -> locateRegion errback -> retry RPC -> (continuation of Deferred@873482707 after retry RPC@886376425)), so the following Deferred is getting paused: Deferred@873482707(state=PAUSED, result=Deferred@234515736, callback=<none>, errback=<none>)
2012-07-25 11:50:36,563 DEBUG [main-EventThread] RegionClient: RPC queued: HBaseRpc(method="getClosestRowBefore", table="-ROOT-", key=".META.,t0,1,:,:", region=RegionInfo(table="-ROOT-", region_name="-ROOT-,,0", stop_key=""), attempt=0)
2012-07-25 11:50:36,563 DEBUG [main-EventThread] Deferred: callback=retry RPC@425645657 returned Deferred@558529042(state=PENDING, result=null, callback=type getClosestRowBefore response -> locateRegion in ROOT -> passthrough -> retry RPC -> (continuation of Deferred@546587857 after retry RPC@425645657), errback=passthrough -> passthrough -> locateRegion errback -> retry RPC -> (continuation of Deferred@546587857 after retry RPC@425645657)), so the following Deferred is getting paused: Deferred@546587857(state=PAUSED, result=Deferred@558529042, callback=<none>, errback=<none>)
2012-07-25 11:50:36,563 DEBUG [main-EventThread] RegionClient: RPC queued: HBaseRpc(method="getClosestRowBefore", table="-ROOT-", key=".META.,t0,1,:,:", region=RegionInfo(table="-ROOT-", region_name="-ROOT-,,0", stop_key=""), attempt=0)
2012-07-25 11:50:36,564 DEBUG [main-EventThread] Deferred: callback=retry RPC@1714554380 returned Deferred@1579889214(state=PENDING, result=null, callback=type getClosestRowBefore response -> locateRegion in ROOT -> passthrough -> retry RPC -> (continuation of Deferred@1710208190 after retry RPC@1714554380), errback=passthrough -> passthrough -> locateRegion errback -> retry RPC -> (continuation of Deferred@1710208190 after retry RPC@1714554380)), so the following Deferred is getting paused: Deferred@1710208190(state=PAUSED, result=Deferred@1579889214, callback=<none>, errback=<none>)
2012-07-25 11:50:36,567 DEBUG [main-EventThread] Deferred: callback=disconnect callback@1223313598 returned Deferred@223205208(state=PENDING, result=null, callback=wait 2 RegionClient.shutdown() -> release resources callback -> (continuation of Deferred@1903483194 after disconnect callback@1223313598), errback=passthrough -> passthrough -> (continuation of Deferred@1903483194 after disconnect callback@1223313598)), so the following Deferred is getting paused: Deferred@1903483194(state=PAUSED, result=Deferred@223205208, callback=<none>, errback=<none>)
2012-07-25 11:50:36,568 DEBUG [main-EventThread] Deferred: callback=retry shutdown@778152199 returned Deferred@1903483194(state=PAUSED, result=Deferred@223205208, callback=(continuation of Deferred@228598363 after retry shutdown@778152199), errback=(continuation of Deferred@228598363 after retry shutdown@778152199)), so the following Deferred is getting paused: Deferred@228598363(state=PAUSED, result=Deferred@1903483194, callback=wakeup thread main, errback=wakeup thread main)
2012-07-25 11:50:36,568 DEBUG [main-EventThread] HBaseClient: Ignore any DEBUG exception from ZooKeeper
2012-07-25 11:50:36,568 DEBUG [main-EventThread] ZooKeeper: Closing session: 0x135ca75f41b6469
2012-07-25 11:50:36,568 DEBUG [main-EventThread] ClientCnxn: Closing client for session: 0x135ca75f41b6469
2012-07-25 11:50:36,586 DEBUG [New I/O  worker #1] RegionClient: [id: 0x6ab30913, /10.241.94.172:61070 => /172.22.0.31:60020] BOUND: /10.241.94.172:61070
2012-07-25 11:50:36,586 DEBUG [New I/O  worker #1] RegionClient: [id: 0x6ab30913, /10.241.94.172:61070 => /172.22.0.31:60020] CONNECTED: /172.22.0.31:60020
2012-07-25 11:50:36,599 DEBUG [main-SendThread(pww-30:2181)] ClientCnxn: Reading reply sessionid:0x135ca75f41b6469, packet:: clientPath:null serverPath:null finished:false header:: 2,-11  replyHeader:: 2,25784858193,0  request:: null response:: null
2012-07-25 11:50:36,599 DEBUG [main-SendThread(pww-30:2181)] ClientCnxn: An exception was thrown while closing send thread for session 0x135ca75f41b6469 : Unable to read additional data from server sessionid 0x135ca75f41b6469, likely server has closed socket
2012-07-25 11:50:36,602 DEBUG [main-EventThread] ClientCnxn: Disconnecting client for session: 0x135ca75f41b6469
2012-07-25 11:50:36,602 INFO  [main-EventThread] ZooKeeper: Session: 0x135ca75f41b6469 closed
2012-07-25 11:50:36,603 DEBUG [main-EventThread] HBaseClient: ZooKeeper#close completed in 34564000ns
2012-07-25 11:50:36,603 INFO  [main-EventThread] ClientCnxn: EventThread shut down
2012-07-25 11:50:36,607 DEBUG [New I/O  worker #1] RegionClient: Sending RPC #0, payload=BigEndianHeapChannelBuffer(ridx=0, widx=87, cap=87) "\x00\x00\x00S\x00\x00\x00\x00\x00\x12getProtocolVersion\x00\x00\x00\x02\n,org.apache.hadoop.hbase.ipc.HRegionInterface\x06\x00\x00\x00\x00\x00\x00\x00\x18"
2012-07-25 11:50:36,609 DEBUG [main-SendThread(pww-30:2181)] ClientCnxn: Ignoring exception during shutdown input
java.net.SocketException: Socket is not connected
    at sun.nio.ch.SocketChannelImpl.shutdown(Native Method) ~[na:1.6.0_32]
    at sun.nio.ch.SocketChannelImpl.shutdownInput(SocketChannelImpl.java:665) ~[na:1.6.0_32]
    at sun.nio.ch.SocketAdaptor.shutdownInput(SocketAdaptor.java:430) ~[na:1.6.0_32]
    at org.apache.zookeeper.ClientCnxn$SendThread.cleanup(ClientCnxn.java:1232) [zookeeper-3.3.4.jar:3.3.3-1203054]
    at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1211) [zookeeper-3.3.4.jar:3.3.3-1203054]
2012-07-25 11:50:36,613 DEBUG [New I/O  worker #1] RegionClient: [id: 0x6ab30913, /10.241.94.172:61070 => /172.22.0.31:60020] WRITTEN_AMOUNT: 226
2012-07-25 11:50:36,641 DEBUG [New I/O  worker #1] RegionClient: [id: 0x6ab30913, /10.241.94.172:61070 => /172.22.0.31:60020] RECEIVED: BigEndianHeapChannelBuffer(ridx=0, widx=22, cap=22)
2012-07-25 11:50:36,641 DEBUG [New I/O  worker #1] RegionClient: ------------------>> ENTERING DECODE >>------------------
2012-07-25 11:50:36,642 DEBUG [New I/O  worker #1] RegionClient: rpcid=0, response size=22 bytes, 0 readable bytes left, rpc=HBaseRpc(method="getProtocolVersion", table=null, key=null, region=null, attempt=0)
2012-07-25 11:50:36,642 DEBUG [New I/O  worker #1] RegionClient: Executing RPC queued: HBaseRpc(method="getClosestRowBefore", table="-ROOT-", key=".META.,t1,0,:,:", region=RegionInfo(table="-ROOT-", region_name="-ROOT-,,0", stop_key=""), attempt=0)
2012-07-25 11:50:36,643 DEBUG [New I/O  worker #1] RegionClient: Sending RPC #1, payload=BigEndianHeapChannelBuffer(ridx=0, widx=80, cap=84) "\x00\x00\x00L\x00\x00\x00\x01\x01\x00\x13getClosestRowBefore\x00\x00\x00\x00\x00\x00\x00\x1D\x00\x00\x00\x00\x00\x00\x00\x03\x0B\t-ROOT-,,0\x0B\x0F.META.,t1,0,:,:\x0B\x04info\x00\x00\x00\x00"
2012-07-25 11:50:36,643 DEBUG [New I/O  worker #1] RegionClient: [id: 0x6ab30913, /10.241.94.172:61070 => /172.22.0.31:60020] WRITTEN_AMOUNT: 80
2012-07-25 11:50:36,643 DEBUG [New I/O  worker #1] RegionClient: Executing RPC queued: HBaseRpc(method="getClosestRowBefore", table="-ROOT-", key=".META.,t1,0,:,:", region=RegionInfo(table="-ROOT-", region_name="-ROOT-,,0", stop_key=""), attempt=0)
2012-07-25 11:50:36,643 DEBUG [New I/O  worker #1] RegionClient: Sending RPC #2, payload=BigEndianHeapChannelBuffer(ridx=0, widx=80, cap=84) "\x00\x00\x00L\x00\x00\x00\x02\x01\x00\x13getClosestRowBefore\x00\x00\x00\x00\x00\x00\x00\x1D\x00\x00\x00\x00\x00\x00\x00\x03\x0B\t-ROOT-,,0\x0B\x0F.META.,t1,0,:,:\x0B\x04info\x00\x00\x00\x00"
2012-07-25 11:50:36,643 DEBUG [New I/O  worker #1] RegionClient: [id: 0x6ab30913, /10.241.94.172:61070 => /172.22.0.31:60020] WRITTEN_AMOUNT: 80
2012-07-25 11:50:36,643 DEBUG [New I/O  worker #1] RegionClient: Executing RPC queued: HBaseRpc(method="getClosestRowBefore", table="-ROOT-", key=".META.,t0,1,:,:", region=RegionInfo(table="-ROOT-", region_name="-ROOT-,,0", stop_key=""), attempt=0)
2012-07-25 11:50:36,643 DEBUG [New I/O  worker #1] RegionClient: Sending RPC #3, payload=BigEndianHeapChannelBuffer(ridx=0, widx=80, cap=84) "\x00\x00\x00L\x00\x00\x00\x03\x01\x00\x13getClosestRowBefore\x00\x00\x00\x00\x00\x00\x00\x1D\x00\x00\x00\x00\x00\x00\x00\x03\x0B\t-ROOT-,,0\x0B\x0F.META.,t0,1,:,:\x0B\x04info\x00\x00\x00\x00"
2012-07-25 11:50:36,643 DEBUG [New I/O  worker #1] RegionClient: [id: 0x6ab30913, /10.241.94.172:61070 => /172.22.0.31:60020] WRITTEN_AMOUNT: 80
2012-07-25 11:50:36,643 DEBUG [New I/O  worker #1] RegionClient: Executing RPC queued: HBaseRpc(method="getClosestRowBefore", table="-ROOT-", key=".META.,t0,1,:,:", region=RegionInfo(table="-ROOT-", region_name="-ROOT-,,0", stop_key=""), attempt=0)
2012-07-25 11:50:36,644 DEBUG [New I/O  worker #1] RegionClient: Sending RPC #4, payload=BigEndianHeapChannelBuffer(ridx=0, widx=80, cap=84) "\x00\x00\x00L\x00\x00\x00\x04\x01\x00\x13getClosestRowBefore\x00\x00\x00\x00\x00\x00\x00\x1D\x00\x00\x00\x00\x00\x00\x00\x03\x0B\t-ROOT-,,0\x0B\x0F.META.,t0,1,:,:\x0B\x04info\x00\x00\x00\x00"
2012-07-25 11:50:36,644 DEBUG [New I/O  worker #1] RegionClient: [id: 0x6ab30913, /10.241.94.172:61070 => /172.22.0.31:60020] WRITTEN_AMOUNT: 80
2012-07-25 11:50:36,644 DEBUG [New I/O  worker #1] RegionClient: ------------------<< LEAVING  DECODE <<------------------ time elapsed: 2463us
2012-07-25 11:50:36,667 DEBUG [New I/O  worker #1] RegionClient: [id: 0x6ab30913, /10.241.94.172:61070 => /172.22.0.31:60020] RECEIVED: BigEndianHeapChannelBuffer(ridx=0, widx=268, cap=268)
2012-07-25 11:50:36,667 DEBUG [New I/O  worker #1] RegionClient: ------------------>> ENTERING DECODE >>------------------
2012-07-25 11:50:36,667 DEBUG [New I/O  worker #1] RegionClient: rpcid=1, response size=268 bytes, 0 readable bytes left, rpc=HBaseRpc(method="getClosestRowBefore", table="-ROOT-", key=".META.,t1,0,:,:", region=RegionInfo(table="-ROOT-", region_name="-ROOT-,,0", stop_key=""), attempt=0)
2012-07-25 11:50:36,667 DEBUG [New I/O  worker #1] RegionInfo: Got ".META."'s region [""-"") offline=false, region_id=1, region_name=".META.,,1", split=false
2012-07-25 11:50:36,668 INFO  [New I/O  worker #1] HBaseClient: Added client for region RegionInfo(table=".META.", region_name=".META.,,1", stop_key=""), which was added to the regions cache.  Now we know that RegionClient@2128040981(chan=[id: 0x6ab30913, /10.241.94.172:61070 => /172.22.0.31:60020], #pending_rpcs=0, #batched=0, #rpcs_inflight=3) is hosting 1 region.
2012-07-25 11:50:36,668 DEBUG [New I/O  worker #1] RegionClient: Sending RPC #5, payload=BigEndianHeapChannelBuffer(ridx=0, widx=71, cap=75) "\x00\x00\x00C\x00\x00\x00\x05\x01\x00\x13getClosestRowBefore\x00\x00\x00\x00\x00\x00\x00\x1D\x00\x00\x00\x00\x00\x00\x00\x03\x0B\t.META.,,1\x0B\x06t1,0,:\x0B\x04info\x00\x00\x00\x00"
2012-07-25 11:50:36,668 DEBUG [New I/O  worker #1] RegionClient: [id: 0x6ab30913, /10.241.94.172:61070 => /172.22.0.31:60020] WRITTEN_AMOUNT: 71
2012-07-25 11:50:36,669 DEBUG [New I/O  worker #1] Deferred: callback=retry RPC@199156736 returned Deferred@1447739926(state=PENDING, result=null, callback=type getClosestRowBefore response -> locateRegion in META -> release .META. lookup permit -> passthrough -> retry RPC -> (continuation of Deferred@240990493 after retry RPC@199156736), errback=passthrough -> passthrough -> release .META. lookup permit -> locateRegion errback -> retry RPC -> (continuation of Deferred@240990493 after retry RPC@199156736)), so the following Deferred is getting paused: Deferred@240990493(state=PAUSED, result=Deferred@1447739926, callback=(continuation of Deferred@173057609 after retry RPC@121398849) -> notify DeferredGroup@1175215772 -> notify DeferredGroup@1444378545, errback=(continuation of Deferred@173057609 after retry RPC@121398849) -> notify DeferredGroup@1175215772 -> notify DeferredGroup@1444378545)
2012-07-25 11:50:36,669 DEBUG [New I/O  worker #1] RegionClient: ------------------<< LEAVING  DECODE <<------------------ time elapsed: 2006us
2012-07-25 11:50:36,669 DEBUG [New I/O  worker #1] RegionClient: [id: 0x6ab30913, /10.241.94.172:61070 => /172.22.0.31:60020] RECEIVED: BigEndianHeapChannelBuffer(ridx=0, widx=536, cap=536)
2012-07-25 11:50:36,669 DEBUG [New I/O  worker #1] RegionClient: ------------------>> ENTERING DECODE >>------------------
2012-07-25 11:50:36,669 DEBUG [New I/O  worker #1] RegionClient: rpcid=2, response size=268 bytes, 268 readable bytes left, rpc=HBaseRpc(method="getClosestRowBefore", table="-ROOT-", key=".META.,t1,0,:,:", region=RegionInfo(table="-ROOT-", region_name="-ROOT-,,0", stop_key=""), attempt=0)
2012-07-25 11:50:36,669 DEBUG [New I/O  worker #1] RegionInfo: Got ".META."'s region [""-"") offline=false, region_id=1, region_name=".META.,,1", split=false
2012-07-25 11:50:36,670 DEBUG [New I/O  worker #1] RegionClient: Sending RPC #6, payload=BigEndianHeapChannelBuffer(ridx=0, widx=71, cap=75) "\x00\x00\x00C\x00\x00\x00\x06\x01\x00\x13getClosestRowBefore\x00\x00\x00\x00\x00\x00\x00\x1D\x00\x00\x00\x00\x00\x00\x00\x03\x0B\t.META.,,1\x0B\x06t1,0,:\x0B\x04info\x00\x00\x00\x00"
2012-07-25 11:50:36,670 DEBUG [New I/O  worker #1] RegionClient: [id: 0x6ab30913, /10.241.94.172:61070 => /172.22.0.31:60020] WRITTEN_AMOUNT: 71
2012-07-25 11:50:36,670 DEBUG [New I/O  worker #1] Deferred: callback=retry RPC@515060127 returned Deferred@108973432(state=PENDING, result=null, callback=type getClosestRowBefore response -> locateRegion in META -> release .META. lookup permit -> passthrough -> retry RPC -> (continuation of Deferred@234515736 after retry RPC@515060127), errback=passthrough -> passthrough -> release .META. lookup permit -> locateRegion errback -> retry RPC -> (continuation of Deferred@234515736 after retry RPC@515060127)), so the following Deferred is getting paused: Deferred@234515736(state=PAUSED, result=Deferred@108973432, callback=(continuation of Deferred@873482707 after retry RPC@886376425) -> notify DeferredGroup@1175215772 -> notify DeferredGroup@1444378545, errback=(continuation of Deferred@873482707 after retry RPC@886376425) -> notify DeferredGroup@1175215772 -> notify DeferredGroup@1444378545)
2012-07-25 11:50:36,670 DEBUG [New I/O  worker #1] RegionClient: ------------------<< LEAVING  DECODE <<------------------ time elapsed: 720us
2012-07-25 11:50:36,670 DEBUG [New I/O  worker #1] RegionClient: ------------------>> ENTERING DECODE >>------------------
2012-07-25 11:50:36,670 DEBUG [New I/O  worker #1] RegionClient: rpcid=3, response size=268 bytes, 0 readable bytes left, rpc=HBaseRpc(method="getClosestRowBefore", table="-ROOT-", key=".META.,t0,1,:,:", region=RegionInfo(table="-ROOT-", region_name="-ROOT-,,0", stop_key=""), attempt=0)
2012-07-25 11:50:36,670 DEBUG [New I/O  worker #1] RegionInfo: Got ".META."'s region [""-"") offline=false, region_id=1, region_name=".META.,,1", split=false
2012-07-25 11:50:36,670 DEBUG [New I/O  worker #1] RegionClient: Sending RPC #7, payload=BigEndianHeapChannelBuffer(ridx=0, widx=71, cap=75) "\x00\x00\x00C\x00\x00\x00\x07\x01\x00\x13getClosestRowBefore\x00\x00\x00\x00\x00\x00\x00\x1D\x00\x00\x00\x00\x00\x00\x00\x03\x0B\t.META.,,1\x0B\x06t0,1,:\x0B\x04info\x00\x00\x00\x00"
2012-07-25 11:50:36,670 DEBUG [New I/O  worker #1] RegionClient: [id: 0x6ab30913, /10.241.94.172:61070 => /172.22.0.31:60020] WRITTEN_AMOUNT: 71
2012-07-25 11:50:36,671 DEBUG [New I/O  worker #1] Deferred: callback=retry RPC@1860404380 returned Deferred@454514340(state=PENDING, result=null, callback=type getClosestRowBefore response -> locateRegion in META -> release .META. lookup permit -> passthrough -> retry RPC -> (continuation of Deferred@558529042 after retry RPC@1860404380), errback=passthrough -> passthrough -> release .META. lookup permit -> locateRegion errback -> retry RPC -> (continuation of Deferred@558529042 after retry RPC@1860404380)), so the following Deferred is getting paused: Deferred@558529042(state=PAUSED, result=Deferred@454514340, callback=(continuation of Deferred@546587857 after retry RPC@425645657) -> notify DeferredGroup@1175215772 -> notify DeferredGroup@1444378545, errback=(continuation of Deferred@546587857 after retry RPC@425645657) -> notify DeferredGroup@1175215772 -> notify DeferredGroup@1444378545)
2012-07-25 11:50:36,671 DEBUG [New I/O  worker #1] RegionClient: ------------------<< LEAVING  DECODE <<------------------ time elapsed: 684us
2012-07-25 11:50:36,686 DEBUG [New I/O  worker #1] RegionClient: [id: 0x6ab30913, /10.241.94.172:61070 => /172.22.0.31:60020] RECEIVED: BigEndianHeapChannelBuffer(ridx=0, widx=268, cap=268)
2012-07-25 11:50:36,686 DEBUG [New I/O  worker #1] RegionClient: ------------------>> ENTERING DECODE >>------------------
2012-07-25 11:50:36,686 DEBUG [New I/O  worker #1] RegionClient: rpcid=4, response size=268 bytes, 0 readable bytes left, rpc=HBaseRpc(method="getClosestRowBefore", table="-ROOT-", key=".META.,t0,1,:,:", region=RegionInfo(table="-ROOT-", region_name="-ROOT-,,0", stop_key=""), attempt=0)
2012-07-25 11:50:36,686 DEBUG [New I/O  worker #1] RegionInfo: Got ".META."'s region [""-"") offline=false, region_id=1, region_name=".META.,,1", split=false
2012-07-25 11:50:36,686 DEBUG [New I/O  worker #1] RegionClient: Sending RPC #8, payload=BigEndianHeapChannelBuffer(ridx=0, widx=71, cap=75) "\x00\x00\x00C\x00\x00\x00\x08\x01\x00\x13getClosestRowBefore\x00\x00\x00\x00\x00\x00\x00\x1D\x00\x00\x00\x00\x00\x00\x00\x03\x0B\t.META.,,1\x0B\x06t0,1,:\x0B\x04info\x00\x00\x00\x00"
2012-07-25 11:50:36,687 DEBUG [New I/O  worker #1] RegionClient: [id: 0x6ab30913, /10.241.94.172:61070 => /172.22.0.31:60020] WRITTEN_AMOUNT: 71
2012-07-25 11:50:36,687 DEBUG [New I/O  worker #1] Deferred: callback=retry RPC@423180001 returned Deferred@2067921590(state=PENDING, result=null, callback=type getClosestRowBefore response -> locateRegion in META -> release .META. lookup permit -> passthrough -> retry RPC -> (continuation of Deferred@1579889214 after retry RPC@423180001), errback=passthrough -> passthrough -> release .META. lookup permit -> locateRegion errback -> retry RPC -> (continuation of Deferred@1579889214 after retry RPC@423180001)), so the following Deferred is getting paused: Deferred@1579889214(state=PAUSED, result=Deferred@2067921590, callback=(continuation of Deferred@1710208190 after retry RPC@1714554380) -> notify DeferredGroup@1175215772 -> notify DeferredGroup@1444378545, errback=(continuation of Deferred@1710208190 after retry RPC@1714554380) -> notify DeferredGroup@1175215772 -> notify DeferredGroup@1444378545)
2012-07-25 11:50:36,687 DEBUG [New I/O  worker #1] RegionClient: ------------------<< LEAVING  DECODE <<------------------ time elapsed: 852us
2012-07-25 11:50:36,696 DEBUG [New I/O  worker #1] RegionClient: [id: 0x6ab30913, /10.241.94.172:61070 => /172.22.0.31:60020] RECEIVED: BigEndianHeapChannelBuffer(ridx=0, widx=392, cap=392)
2012-07-25 11:50:36,696 DEBUG [New I/O  worker #1] RegionClient: ------------------>> ENTERING DECODE >>------------------
2012-07-25 11:50:36,696 DEBUG [New I/O  worker #1] RegionClient: rpcid=5, response size=392 bytes, 0 readable bytes left, rpc=HBaseRpc(method="getClosestRowBefore", table=".META.", key="t1,0,:", region=RegionInfo(table=".META.", region_name=".META.,,1", stop_key=""), attempt=0)
2012-07-25 11:50:36,696 DEBUG [New I/O  worker #1] RegionInfo: Got "t1"'s region [""-"") offline=false, region_id=1343241605007, region_name="t1,,1343241605007.89bcf35b2666c0a5a6187372da617e0b.", split=false
2012-07-25 11:50:36,697 INFO  [New I/O  worker #1] HBaseClient: Added client for region RegionInfo(table="t1", region_name="t1,,1343241605007.89bcf35b2666c0a5a6187372da617e0b.", stop_key=""), which was added to the regions cache.  Now we know that RegionClient@2128040981(chan=[id: 0x6ab30913, /10.241.94.172:61070 => /172.22.0.31:60020], #pending_rpcs=0, #batched=0, #rpcs_inflight=3) is hosting 2 regions.
2012-07-25 11:50:36,701 DEBUG [New I/O  worker #1] Deferred: callback=retry RPC@1505888432 returned Deferred@1372096729(state=PENDING, result=null, callback=(continuation of Deferred@1447739926 after retry RPC@1505888432), errback=(continuation of Deferred@1447739926 after retry RPC@1505888432)), so the following Deferred is getting paused: Deferred@1447739926(state=PAUSED, result=Deferred@1372096729, callback=(continuation of Deferred@240990493 after retry RPC@199156736), errback=(continuation of Deferred@240990493 after retry RPC@199156736))
2012-07-25 11:50:36,701 DEBUG [New I/O  worker #1] RegionClient: ------------------<< LEAVING  DECODE <<------------------ time elapsed: 5409us
2012-07-25 11:50:36,702 DEBUG [New I/O  worker #1] RegionClient: [id: 0x6ab30913, /10.241.94.172:61070 => /172.22.0.31:60020] RECEIVED: BigEndianHeapChannelBuffer(ridx=0, widx=784, cap=784)
2012-07-25 11:50:36,702 DEBUG [New I/O  worker #1] RegionClient: ------------------>> ENTERING DECODE >>------------------
2012-07-25 11:50:36,702 DEBUG [New I/O  worker #1] RegionClient: rpcid=6, response size=392 bytes, 392 readable bytes left, rpc=HBaseRpc(method="getClosestRowBefore", table=".META.", key="t1,0,:", region=RegionInfo(table=".META.", region_name=".META.,,1", stop_key=""), attempt=0)
2012-07-25 11:50:36,702 DEBUG [New I/O  worker #1] RegionInfo: Got "t1"'s region [""-"") offline=false, region_id=1343241605007, region_name="t1,,1343241605007.89bcf35b2666c0a5a6187372da617e0b.", split=false
2012-07-25 11:50:36,702 DEBUG [New I/O  worker #1] Deferred: callback=retry RPC@1150322817 returned Deferred@1827795025(state=PENDING, result=null, callback=(continuation of Deferred@108973432 after retry RPC@1150322817), errback=(continuation of Deferred@108973432 after retry RPC@1150322817)), so the following Deferred is getting paused: Deferred@108973432(state=PAUSED, result=Deferred@1827795025, callback=(continuation of Deferred@234515736 after retry RPC@515060127), errback=(continuation of Deferred@234515736 after retry RPC@515060127))
2012-07-25 11:50:36,702 DEBUG [New I/O  worker #1] RegionClient: ------------------<< LEAVING  DECODE <<------------------ time elapsed: 471us
2012-07-25 11:50:36,702 DEBUG [New I/O  worker #1] RegionClient: ------------------>> ENTERING DECODE >>------------------
2012-07-25 11:50:36,702 DEBUG [New I/O  worker #1] RegionClient: rpcid=7, response size=392 bytes, 0 readable bytes left, rpc=HBaseRpc(method="getClosestRowBefore", table=".META.", key="t0,1,:", region=RegionInfo(table=".META.", region_name=".META.,,1", stop_key=""), attempt=0)
2012-07-25 11:50:36,702 DEBUG [New I/O  worker #1] RegionInfo: Got "t0"'s region [""-"") offline=false, region_id=1342830171798, region_name="t0,,1342830171798.892d1127298fd308960c5c8173264038.", split=false
2012-07-25 11:50:36,702 INFO  [New I/O  worker #1] HBaseClient: Added client for region RegionInfo(table="t0", region_name="t0,,1342830171798.892d1127298fd308960c5c8173264038.", stop_key=""), which was added to the regions cache.  Now we know that RegionClient@2128040981(chan=[id: 0x6ab30913, /10.241.94.172:61070 => /172.22.0.31:60020], #pending_rpcs=0, #batched=2, #rpcs_inflight=1) is hosting 3 regions.
2012-07-25 11:50:36,703 DEBUG [New I/O  worker #1] Deferred: callback=retry RPC@2144898487 returned Deferred@1648372467(state=PENDING, result=null, callback=(continuation of Deferred@454514340 after retry RPC@2144898487), errback=(continuation of Deferred@454514340 after retry RPC@2144898487)), so the following Deferred is getting paused: Deferred@454514340(state=PAUSED, result=Deferred@1648372467, callback=(continuation of Deferred@558529042 after retry RPC@1860404380), errback=(continuation of Deferred@558529042 after retry RPC@1860404380))
2012-07-25 11:50:36,703 DEBUG [New I/O  worker #1] RegionClient: ------------------<< LEAVING  DECODE <<------------------ time elapsed: 540us
2012-07-25 11:50:36,705 DEBUG [New I/O  worker #1] RegionClient: [id: 0x6ab30913, /10.241.94.172:61070 => /172.22.0.31:60020] RECEIVED: BigEndianHeapChannelBuffer(ridx=0, widx=392, cap=392)
2012-07-25 11:50:36,706 DEBUG [New I/O  worker #1] RegionClient: ------------------>> ENTERING DECODE >>------------------
2012-07-25 11:50:36,706 DEBUG [New I/O  worker #1] RegionClient: rpcid=8, response size=392 bytes, 0 readable bytes left, rpc=HBaseRpc(method="getClosestRowBefore", table=".META.", key="t0,1,:", region=RegionInfo(table=".META.", region_name=".META.,,1", stop_key=""), attempt=0)
2012-07-25 11:50:36,706 DEBUG [New I/O  worker #1] RegionInfo: Got "t0"'s region [""-"") offline=false, region_id=1342830171798, region_name="t0,,1342830171798.892d1127298fd308960c5c8173264038.", split=false
2012-07-25 11:50:36,706 DEBUG [New I/O  worker #1] Deferred: callback=retry RPC@1657006569 returned Deferred@741470887(state=PENDING, result=null, callback=(continuation of Deferred@2067921590 after retry RPC@1657006569), errback=(continuation of Deferred@2067921590 after retry RPC@1657006569)), so the following Deferred is getting paused: Deferred@2067921590(state=PAUSED, result=Deferred@741470887, callback=(continuation of Deferred@1579889214 after retry RPC@423180001), errback=(continuation of Deferred@1579889214 after retry RPC@423180001))
2012-07-25 11:50:36,706 DEBUG [New I/O  worker #1] RegionClient: ------------------<< LEAVING  DECODE <<------------------ time elapsed: 600us
2012-07-25 11:50:37,601 DEBUG [Hashed wheel timer #1] RegionClient: Periodic flush timer: flushing RPCs for RegionClient@2128040981(chan=[id: 0x6ab30913, /10.241.94.172:61070 => /172.22.0.31:60020], #pending_rpcs=0, #batched=4, #rpcs_inflight=0)
2012-07-25 11:50:37,602 DEBUG [Hashed wheel timer #1] RegionClient: Sending RPC #9, payload=BigEndianHeapChannelBuffer(ridx=0, widx=382, cap=404) [0, 0, 1, 122, 0, 0, 0, 9, 1, 0, 5, 109, 117, 108, 116, 105, 0, 0, 0, 0, 0, 0, 0, 29, 0, 0, 0, 0, 0, 0, 0, 1, 66, 66, 0, 0, 0, 2, 51, 116, 48, 44, 44, 49, 51, 52, 50, 56, 51, 48, 49, 55, 49, 55, 57, 56, 46, 56, 57, 50, 100, 49, 49, 50, 55, 50, 57, 56, 102, 100, 51, 48, 56, 57, 54, 48, 99, 53, 99, 56, 49, 55, 51, 50, 54, 52, 48, 51, 56, 46, 0, 0, 0, 2, 65, 65, 64, 31, 3, 1, 49, 127, -1, -1, -1, -1, -1, -1, -1, -1, -1, -1, -1, -1, -1, -1, -1, 1, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 14, 17, 14, 65, 65, 64, 35, 2, 1, 49, 127, -1, -1, -1, -1, -1, -1, -1, -1, -1, -1, -1, -1, -1, -1, -1, 1, 0, 0, 0, 1, 1, 102, 0, 0, 0, 0, 0, 0, 0, 28, 0, 0, 0, 24, 0, 0, 0, 15, 0, 0, 0, 1, 0, 1, 49, 1, 102, 113, 127, -1, -1, -1, -1, -1, -1, -1, 4, 118, 0, 0, 0, 0, 0, 0, 0, 1, 14, 17, 14, 51, 116, 49, 44, 44, 49, 51, 52, 51, 50, 52, 49, 54, 48, 53, 48, 48, 55, 46, 56, 57, 98, 99, 102, 51, 53, 98, 50, 54, 54, 54, 99, 48, 97, 53, 97, 54, 49, 56, 55, 51, 55, 50, 100, 97, 54, 49, 55, 101, 48, 98, 46, 0, 0, 0, 2, 65, 65, 64, 31, 3, 1, 48, 127, -1, -1, -1, -1, -1, -1, -1, -1, -1, -1, -1, -1, -1, -1, -1, 1, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 14, 17, 14, 65, 65, 64, 35, 2, 1, 48, 127, -1, -1, -1, -1, -1, -1, -1, -1, -1, -1, -1, -1, -1, -1, -1, 1, 0, 0, 0, 1, 1, 102, 0, 0, 0, 1, 0, 0, 0, 28, 0, 0, 0, 24, 0, 0, 0, 15, 0, 0, 0, 1, 0, 1, 48, 1, 102, 113, 127, -1, -1, -1, -1, -1, -1, -1, 4, 118, 0, 0, 0, 0, 0, 0, 0, 1, 14, 17, 14, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]
2012-07-25 11:50:37,603 DEBUG [New I/O  worker #1] RegionClient: [id: 0x6ab30913, /10.241.94.172:61070 => /172.22.0.31:60020] WRITTEN_AMOUNT: 382
2012-07-25 11:50:37,633 DEBUG [New I/O  worker #1] RegionClient: [id: 0x6ab30913, /10.241.94.172:61070 => /172.22.0.31:60020] RECEIVED: BigEndianHeapChannelBuffer(ridx=0, widx=102, cap=102)
2012-07-25 11:50:37,633 DEBUG [New I/O  worker #1] RegionClient: ------------------>> ENTERING DECODE >>------------------
2012-07-25 11:50:37,634 DEBUG [New I/O  worker #1] RegionClient: rpcid=9, response size=102 bytes, 0 readable bytes left, rpc=MultiAction(batch=[DeleteRequest(table="t0", key="1", family="", qualifiers=[""], attempt=4, region=RegionInfo(table="t0", region_name="t0,,1342830171798.892d1127298fd308960c5c8173264038.", stop_key="")), PutRequest(table="t0", key="1", family="f", qualifiers=["q"], values=["v"], timestamp=9223372036854775807, lockid=-1, durable=true, bufferable=true, attempt=4, region=RegionInfo(table="t0", region_name="t0,,1342830171798.892d1127298fd308960c5c8173264038.", stop_key="")), DeleteRequest(table="t1", key="0", family="", qualifiers=[""], attempt=4, region=RegionInfo(table="t1", region_name="t1,,1343241605007.89bcf35b2666c0a5a6187372da617e0b.", stop_key="")), PutRequest(table="t1", key="0", family="f", qualifiers=["q"], values=["v"], timestamp=9223372036854775807, lockid=-1, durable=true, bufferable=true, attempt=4, region=RegionInfo(table="t1", region_name="t1,,1343241605007.89bcf35b2666c0a5a6187372da617e0b.", stop_key=""))])
2012-07-25 11:50:37,634 DEBUG [New I/O  worker #1] RegionClient: ------------------<< LEAVING  DECODE <<------------------ time elapsed: 1434us
Exception in thread "main" com.stumbleupon.async.DeferredGroupException: At least one of the Deferreds failed, first exception:
    at com.stumbleupon.async.DeferredGroup.recordCompletion(DeferredGroup.java:107)
    at com.stumbleupon.async.DeferredGroup.access$000(DeferredGroup.java:36)
    at com.stumbleupon.async.DeferredGroup$1Notify.call(DeferredGroup.java:69)
    at com.stumbleupon.async.Deferred.doCall(Deferred.java:1261)
    at com.stumbleupon.async.Deferred.runCallbacks(Deferred.java:1240)
    at com.stumbleupon.async.Deferred.callback(Deferred.java:988)
    at com.stumbleupon.async.DeferredGroup.recordCompletion(DeferredGroup.java:107)
    at com.stumbleupon.async.DeferredGroup.access$000(DeferredGroup.java:36)
    at com.stumbleupon.async.DeferredGroup$1Notify.call(DeferredGroup.java:69)
    at com.stumbleupon.async.Deferred.doCall(Deferred.java:1261)
    at com.stumbleupon.async.Deferred.runCallbacks(Deferred.java:1240)
    at com.stumbleupon.async.Deferred.access$300(Deferred.java:430)
    at com.stumbleupon.async.Deferred$Continue.call(Deferred.java:1349)
    at com.stumbleupon.async.Deferred.doCall(Deferred.java:1261)
    at com.stumbleupon.async.Deferred.runCallbacks(Deferred.java:1240)
    at com.stumbleupon.async.Deferred.access$300(Deferred.java:430)
    at com.stumbleupon.async.Deferred$Continue.call(Deferred.java:1349)
    at com.stumbleupon.async.Deferred.doCall(Deferred.java:1261)
    at com.stumbleupon.async.Deferred.runCallbacks(Deferred.java:1240)
    at com.stumbleupon.async.Deferred.callback(Deferred.java:988)
    at org.hbase.async.HBaseRpc.callback(HBaseRpc.java:443)
    at org.hbase.async.RegionClient$1MultiActionCallback.handleException(RegionClient.java:663)
    at org.hbase.async.RegionClient$1MultiActionCallback.call(RegionClient.java:630)
    at com.stumbleupon.async.Deferred.doCall(Deferred.java:1261)
    at com.stumbleupon.async.Deferred.runCallbacks(Deferred.java:1240)
    at com.stumbleupon.async.Deferred.callback(Deferred.java:988)
    at org.hbase.async.HBaseRpc.callback(HBaseRpc.java:443)
    at org.hbase.async.RegionClient.decode(RegionClient.java:1114)
    at org.hbase.async.RegionClient.decode(RegionClient.java:82)
    at org.jboss.netty.handler.codec.replay.ReplayingDecoder.callDecode(ReplayingDecoder.java:502)
    at org.jboss.netty.handler.codec.replay.ReplayingDecoder.messageReceived(ReplayingDecoder.java:437)
    at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:75)
    at org.hbase.async.RegionClient.handleUpstream(RegionClient.java:938)
    at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:563)
    at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:558)
    at org.hbase.async.HBaseClient$RegionClientPipeline.sendUpstream(HBaseClient.java:2425)
    at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:268)
    at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:255)
    at org.jboss.netty.channel.socket.nio.NioWorker.read(NioWorker.java:91)
    at org.jboss.netty.channel.socket.nio.AbstractNioWorker.processSelectedKeys(AbstractNioWorker.java:373)
    at org.jboss.netty.channel.socket.nio.AbstractNioWorker.run(AbstractNioWorker.java:247)
    at org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:35)
    at org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunnable.java:102)
    at org.jboss.netty.util.internal.DeadLockProofWorker$1.run(DeadLockProofWorker.java:42)
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
    at java.lang.Thread.run(Thread.java:680)
Caused by: com.stumbleupon.async.DeferredGroupException: At least one of the Deferreds failed, first exception:
    ... 41 more
Caused by: org.hbase.async.RemoteException: IPC server unable to read call parameters: Error in readFields
    at org.hbase.async.RegionClient.deserializeException(RegionClient.java:1186)
    at org.hbase.async.RegionClient.deserialize(RegionClient.java:1161)
    at org.hbase.async.RegionClient.decode(RegionClient.java:1082)
    ... 19 more

server log:

2012-07-25 14:50:34,946 WARN org.apache.hadoop.ipc.HBaseServer: Unable to read call parameters for client 192.168.100.252
java.io.IOException: Error in readFields
    at org.apache.hadoop.hbase.io.HbaseObjectWritable.readObject(HbaseObjectWritable.java:655)
    at org.apache.hadoop.hbase.ipc.Invocation.readFields(Invocation.java:125)
    at org.apache.hadoop.hbase.ipc.HBaseServer$Connection.processData(HBaseServer.java:1238)
    at org.apache.hadoop.hbase.ipc.HBaseServer$Connection.readAndProcess(HBaseServer.java:1167)
    at org.apache.hadoop.hbase.ipc.HBaseServer$Listener.doRead(HBaseServer.java:703)
    at org.apache.hadoop.hbase.ipc.HBaseServer$Listener$Reader.doRunLoop(HBaseServer.java:495)
    at org.apache.hadoop.hbase.ipc.HBaseServer$Listener$Reader.run(HBaseServer.java:470)
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
    at java.lang.Thread.run(Thread.java:619)
Caused by: java.io.IOException: Error in readFields
    at org.apache.hadoop.hbase.io.HbaseObjectWritable.readObject(HbaseObjectWritable.java:655)
    at org.apache.hadoop.hbase.io.HbaseObjectWritable.readObject(HbaseObjectWritable.java:565)
    at org.apache.hadoop.hbase.client.MultiAction.readFields(MultiAction.java:116)
    at org.apache.hadoop.hbase.io.HbaseObjectWritable.readObject(HbaseObjectWritable.java:652)
    ... 9 more
Caused by: java.io.IOException: Error in readFields
    at org.apache.hadoop.hbase.io.HbaseObjectWritable.readObject(HbaseObjectWritable.java:655)
    at org.apache.hadoop.hbase.io.HbaseObjectWritable.readObject(HbaseObjectWritable.java:565)
    at org.apache.hadoop.hbase.client.Action.readFields(Action.java:101)
    at org.apache.hadoop.hbase.io.HbaseObjectWritable.readObject(HbaseObjectWritable.java:652)
    ... 12 more
Caused by: java.lang.NegativeArraySizeException: -1
    at org.apache.hadoop.hbase.util.Bytes.readByteArray(Bytes.java:147)
    at org.apache.hadoop.hbase.client.OperationWithAttributes.readAttributes(OperationWithAttributes.java:102)
    at org.apache.hadoop.hbase.client.Put.readFields(Put.java:399)
    at org.apache.hadoop.hbase.io.HbaseObjectWritable.readObject(HbaseObjectWritable.java:652)
    ... 15 more
tsuna commented 12 years ago

Thanks for the report, I'm looking at this tonight.

tsuna commented 12 years ago

I spent a few minutes staring at the code. I can reproduce the bug, but I don't see anything wrong right off the bat. I'll have to spend a bit more time on this one to untangle each byte of the serialized payload to see where I've gone wrong. I'll look at this again tomorrow.

tsuna commented 12 years ago

Sorry I switched to a new laptop on Monday, I still don't have everything transfered over. Will continue looking at this once I have all my files transfered and whatnot. I also need to re-install HomeBrew and all that, so just hold your breath while I recompile the world.

shrijeet commented 12 years ago

Thanks for following up. Also opened (unrelated to this) #34 . Thanks Benoit.

tsuna commented 12 years ago

Hmm, looks like I still need to follow up on this one.

ylangisc commented 12 years ago

This seems to be exactly the same issue I reported in #25.

tsuna commented 12 years ago

Yes this is a duplicate of #25. Thanks a lot @shrijeet for providing code to reproduce the bug. That was tremendously helpful. I added it to a regression test. I started to write a few trivial integration tests. I want to keep adding more to get decent code coverage of asynchbase running against a real HBase instance.