HBASE-23333 Provide call context around timeouts and other failure scenarios

hbase-client/src/main/java/org/apache/hadoop/hbase/ipc/BlockingRpcConnection.java

@@ -149,7 +149,7 @@ public CallSender(String name, Configuration conf) {
 
     public void sendCall(final Call call) throws IOException {
       if (callsToWrite.size() >= maxQueueSize) {
-        throw new IOException("Can't add the call " + call.id
+        throw new IOException("Can't add " + call.toShortString()
             + " to the write queue. callsToWrite.size()=" + callsToWrite.size());
       }
       callsToWrite.offer(call);
@@ -161,7 +161,7 @@ public void remove(Call call) {
       // By removing the call from the expected call list, we make the list smaller, but
       // it means as well that we don't know how many calls we cancelled.
       calls.remove(call.id);
-      call.setException(new CallCancelledException("Call id=" + call.id + ", waitTime="
+      call.setException(new CallCancelledException(call.toShortString() + ", waitTime="
           + (EnvironmentEdgeManager.currentTime() - call.getStartTime()) + ", rpcTimeout="
           + call.timeout));
     }
@@ -193,9 +193,7 @@ public void run() {
           } catch (IOException e) {
             // exception here means the call has not been added to the pendingCalls yet, so we need
             // to fail it by our own.
-            if (LOG.isDebugEnabled()) {
-              LOG.debug("call write error for call #" + call.id, e);
-            }
+            LOG.debug("call write error for {}", call.toShortString());
             call.setException(e);
             closeConn(e);
           }
@@ -628,7 +626,7 @@ private void writeRequest(Call call) throws IOException {
         call.callStats.setRequestSizeBytes(write(this.out, requestHeader, call.param, cellBlock));
       } catch (Throwable t) {
         if(LOG.isTraceEnabled()) {
-          LOG.trace("Error while writing call, call_id:" + call.id, t);
+          LOG.trace("Error while writing {}", call.toShortString());
         }
         IOException e = IPCUtil.toIOE(t);
         closeConn(e);

hbase-client/src/main/java/org/apache/hadoop/hbase/ipc/Call.java

@@ -17,21 +17,21 @@
  */
 package org.apache.hadoop.hbase.ipc;
 
-import org.apache.hbase.thirdparty.io.netty.util.Timeout;
-
-import org.apache.hbase.thirdparty.com.google.protobuf.Descriptors;
-import org.apache.hbase.thirdparty.com.google.protobuf.Message;
-import org.apache.hbase.thirdparty.com.google.protobuf.RpcCallback;
-import org.apache.hadoop.hbase.shaded.protobuf.ProtobufUtil;
-
 import java.io.IOException;
-
+import java.util.Optional;
+import org.apache.commons.lang3.builder.ToStringBuilder;
+import org.apache.commons.lang3.builder.ToStringStyle;
 import org.apache.hadoop.hbase.CellScanner;
-import org.apache.yetus.audience.InterfaceAudience;
 import org.apache.hadoop.hbase.client.MetricsConnection;
 import org.apache.hadoop.hbase.util.EnvironmentEdgeManager;
 import org.apache.htrace.core.Span;
 import org.apache.htrace.core.Tracer;
+import org.apache.yetus.audience.InterfaceAudience;
+import org.apache.hbase.thirdparty.com.google.protobuf.Descriptors;
+import org.apache.hbase.thirdparty.com.google.protobuf.Message;
+import org.apache.hbase.thirdparty.com.google.protobuf.RpcCallback;
+import org.apache.hbase.thirdparty.io.netty.util.Timeout;
+import org.apache.hadoop.hbase.shaded.protobuf.ProtobufUtil;
 
 /** A call waiting for a value. */
 @InterfaceAudience.Private
@@ -56,7 +56,7 @@ class Call {
   final int timeout; // timeout in millisecond for this call; 0 means infinite.
   final int priority;
   final MetricsConnection.CallStats callStats;
-  final RpcCallback<Call> callback;
+  private final RpcCallback<Call> callback;
   final Span span;
   Timeout timeoutTask;
 
@@ -76,10 +76,24 @@ protected Call(int id, final Descriptors.MethodDescriptor md, Message param,
     this.span = Tracer.getCurrentSpan();
   }
 
+  /**
+   * Builds a simplified {@link #toString()} that includes just the id and method name.
+   */
+  public String toShortString() {
+    return new ToStringBuilder(this, ToStringStyle.SHORT_PREFIX_STYLE)
+      .append("id", id)
+      .append("methodName", md.getName())
+      .toString();
+  }
+
   @Override
   public String toString() {
-    return "callId: " + this.id + " methodName: " + this.md.getName() + " param {"
-        + (this.param != null ? ProtobufUtil.getShortTextFormat(this.param) : "") + "}";
+    return new ToStringBuilder(this, ToStringStyle.SHORT_PREFIX_STYLE)
+      .appendSuper(toShortString())
+      .append("param", Optional.ofNullable(param)
+        .map(ProtobufUtil::getShortTextFormat)
+        .orElse(""))
+      .toString();
   }
 
   /**

hbase-client/src/main/java/org/apache/hadoop/hbase/ipc/IPCUtil.java

@@ -230,7 +230,7 @@ static IOException wrapException(InetSocketAddress addr, Throwable error) {
   }
 
   static void setCancelled(Call call) {
-    call.setException(new CallCancelledException("Call id=" + call.id + ", waitTime="
+    call.setException(new CallCancelledException(call.toShortString() + ", waitTime="
         + (EnvironmentEdgeManager.currentTime() - call.getStartTime()) + ", rpcTimeout="
         + call.timeout));
   }

hbase-client/src/main/java/org/apache/hadoop/hbase/ipc/RpcConnection.java

@@ -196,7 +196,7 @@ protected void scheduleTimeoutTask(final Call call) {
 
         @Override
         public void run(Timeout timeout) throws Exception {
-          call.setTimeout(new CallTimeoutException("Call id=" + call.id + ", waitTime="
+          call.setTimeout(new CallTimeoutException(call.toShortString() + ", waitTime="
               + (EnvironmentEdgeManager.currentTime() - call.getStartTime()) + ", rpcTimeout="
               + call.timeout));
           callTimeout(call);

hbase-common/src/test/java/org/apache/hadoop/hbase/util/TestFutureUtils.java

@@ -80,6 +80,8 @@ public void testRecordStackTrace() throws IOException {
         startsWith("org.apache.hadoop.hbase.util.TestFutureUtils.testRecordStackTrace"));
       assertTrue(Stream.of(elements)
         .anyMatch(element -> element.toString().contains("--------Future.get--------")));
+    } catch (Throwable t) {
+      throw new AssertionError("Caught unexpected Throwable", t);
     }
   }
 }