[java client] Implement RPC tracing, part 2

This patch adds pretty printing for the traces, and makes them always part
of KuduRPC.toString. We thus rely on the exceptions' messages to include
the RPC's string representation in order to propagate the traces back to
the user.

In the future we could entertain having the traces in some queryable fashion in
KuduException, either by embedding the KuduRpc or just the list of traces.

Here's a trace snippet where a tserver that had a leader tablet was killed and we're
spinning on finding the new leader:

[0ms] sending RPC to server 5df1a37bd7e14380b5a8fceeba6b0d07
[70ms] received from server 5df1a37bd7e14380b5a8fceeba6b0d07 response Network error: [Peer 5df1a37bd7e14380b5a8fceeba6b0d07] Connection reset
[70ms] delaying RPC due to Network error: [Peer 5df1a37bd7e14380b5a8fceeba6b0d07] Connection reset
[101ms] querying master
[101ms] Sub rpc: GetTableLocations sending RPC to server e6e499debd804a8183b85d20a33ad560
[104ms] Sub rpc: GetTableLocations sending RPC to server e6e499debd804a8183b85d20a33ad560
[104ms] Sub rpc: GetTableLocations received from server e6e499debd804a8183b85d20a33ad560 response OK
[109ms] sending RPC to server 5df1a37bd7e14380b5a8fceeba6b0d07
[110ms] received from server 5df1a37bd7e14380b5a8fceeba6b0d07 response Network error: [Peer 5df1a37bd7e14380b5a8fceeba6b0d07] Connection reset

Change-Id: I2c37143a587971f0e8985c59f4ab1d0c164c3723
Reviewed-on: http://gerrit.cloudera.org:8080/4950
Reviewed-by: Adar Dembo <[email protected]>
Tested-by: Kudu Jenkins

java/kudu-client/src/main/java/org/apache/kudu/client/KuduRpc.java

@@ -341,11 +341,11 @@ public String toString() {
     }
     buf.append(", attempt=").append(attempt);
     buf.append(", ").append(deadlineTracker);
+    buf.append(", ").append(RpcTraceFrame.getHumanReadableStringForTraces(traces));
     // Cheating a bit, we're not actually logging but we'll augment the information provided by
     // this method if DEBUG is enabled.
     if (LOG.isDebugEnabled()) {
       buf.append(", ").append(deferred);
-      buf.append(", ").append(traces);
     }
     buf.append(')');
     return buf.toString();

java/kudu-client/src/main/java/org/apache/kudu/client/RpcTraceFrame.java

@@ -19,6 +19,8 @@
 import com.google.common.base.MoreObjects;
 import org.apache.kudu.annotations.InterfaceAudience;
 
+import java.util.List;
+
 /**
  * Container class for traces. Most of its properties can be null, when they aren't set via the
  * builder. The timestamp is set automatically.
@@ -27,16 +29,43 @@
 class RpcTraceFrame {
   enum Action {
     // Just before putting the RPC on the wire.
-    SEND_TO_SERVER,
+    SEND_TO_SERVER {
+      void appendToStringBuilder(RpcTraceFrame trace, StringBuilder sb) {
+        sb.append("sending RPC to server ");
+        sb.append(trace.getServer().getUuid());
+      }
+    },
     // Just after parsing the response from the server.
-    RECEIVE_FROM_SERVER,
+    RECEIVE_FROM_SERVER {
+      void appendToStringBuilder(RpcTraceFrame trace, StringBuilder sb) {
+        sb.append("received from server ");
+        sb.append(trace.getServer().getUuid());
+        sb.append(" response ");
+        sb.append(trace.getStatus());
+      }
+    },
     // Just before sleeping and then retrying.
-    SLEEP_THEN_RETRY,
+    SLEEP_THEN_RETRY {
+      void appendToStringBuilder(RpcTraceFrame trace, StringBuilder sb) {
+        sb.append("delaying RPC due to ");
+        sb.append(trace.getStatus());
+      }
+    },
     // After having figured out that we don't know where the RPC is going,
     // before querying the master.
-    QUERY_MASTER,
+    QUERY_MASTER {
+      void appendToStringBuilder(RpcTraceFrame trace, StringBuilder sb) {
+        sb.append("querying master");
+      }
+    },
     // Once the trace becomes too large, will be the last trace object in the list.
-    TRACE_TRUNCATED
+    TRACE_TRUNCATED {
+      void appendToStringBuilder(RpcTraceFrame trace, StringBuilder sb) {
+        sb.append("trace too long, truncated");
+      }
+    };
+
+    abstract void appendToStringBuilder(RpcTraceFrame trace, StringBuilder sb);
   }
 
   private final String rpcMethod;
@@ -74,6 +103,39 @@ public Status getStatus() {
     return callStatus;
   }
 
+  public static String getHumanReadableStringForTraces(List<RpcTraceFrame> traces) {
+    String rootMethod;
+    long baseTimestamp;
+    if (traces.isEmpty()) {
+      return "No traces";
+    } else {
+      RpcTraceFrame firstTrace = traces.get(0);
+      rootMethod = firstTrace.getRpcMethod();
+      baseTimestamp = firstTrace.getTimestampMs();
+    }
+
+    StringBuilder sb = new StringBuilder("Traces: ");
+    for (int i = 0; i < traces.size(); i++) {
+      RpcTraceFrame trace = traces.get(i);
+      sb.append('[');
+      sb.append(trace.getTimestampMs() - baseTimestamp);
+      sb.append("ms] ");
+
+      if (!rootMethod.equals(trace.getRpcMethod())) {
+        sb.append("Sub rpc: ");
+        sb.append(trace.getRpcMethod());
+        sb.append(" ");
+      }
+
+      trace.getAction().appendToStringBuilder(trace, sb);
+
+      if (i < traces.size() - 1) {
+        sb.append(", ");
+      }
+    }
+    return sb.toString();
+  }
+
   @Override
   public String toString() {
     return MoreObjects.toStringHelper(this)