HBASE-8366 HBaseServer logs the full query

git-svn-id: https://svn.apache.org/repos/asf/hbase/trunk@1486232 13f79535-47bb-0310-9956-ffa450edef68

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

@@ -28,17 +28,14 @@ import java.nio.ByteBuffer;
 import org.apache.commons.io.IOUtils;
 import org.apache.commons.logging.Log;
 import org.apache.commons.logging.LogFactory;
-import org.apache.hadoop.conf.Configuration;
 import org.apache.hadoop.conf.Configurable;
+import org.apache.hadoop.conf.Configuration;
 import org.apache.hadoop.hbase.CellScanner;
 import org.apache.hadoop.hbase.codec.Codec;
 import org.apache.hadoop.hbase.io.ByteBufferOutputStream;
 import org.apache.hadoop.hbase.protobuf.generated.ClientProtos.ScanRequest;
-import org.apache.hadoop.hbase.protobuf.generated.ClientProtos.ScanResponse;
 import org.apache.hadoop.hbase.protobuf.generated.RegionServerStatusProtos.RegionServerReportRequest;
-import org.apache.hadoop.hbase.protobuf.generated.RegionServerStatusProtos.RegionServerReportResponse;
 import org.apache.hadoop.hbase.protobuf.generated.RegionServerStatusProtos.RegionServerStartupRequest;
-import org.apache.hadoop.hbase.protobuf.generated.RegionServerStatusProtos.RegionServerStartupResponse;
 import org.apache.hadoop.hbase.util.Bytes;
 import org.apache.hadoop.io.compress.CodecPool;
 import org.apache.hadoop.io.compress.CompressionCodec;
@@ -270,24 +267,4 @@ class IPCUtil {
     Preconditions.checkArgument(totalSize < Integer.MAX_VALUE);
     return totalSize;
   }
-
-  /**
-   * Return short version of Param Message toString'd, shorter than TextFormat#regionServerStartup
-   * @param methodName
-   * @param request
-   * @return toString of passed <code>param</code>
-   */
-  static String getRequestShortTextFormat(Message request) {
-    if (request instanceof ScanRequest) {
-      return TextFormat.shortDebugString(request);
-    } else if (request instanceof RegionServerReportRequest) {
-      // Print a short message only, just the servername and the requests, not the full load.
-      RegionServerReportRequest r = (RegionServerReportRequest)request;
-      return "server " + TextFormat.shortDebugString(r.getServer()) +
-        " load { numberOfRequests: " + r.getLoad().getNumberOfRequests() + " }";
-    } else if (request instanceof RegionServerStartupRequest) {
-      return TextFormat.shortDebugString(request);
-    }
-    return "TODO " + TextFormat.shortDebugString(request);
-  }
 }

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

@@ -57,6 +57,7 @@ import org.apache.hadoop.hbase.HConstants;
 import org.apache.hadoop.hbase.ServerName;
 import org.apache.hadoop.hbase.codec.Codec;
 import org.apache.hadoop.hbase.codec.KeyValueCodec;
+import org.apache.hadoop.hbase.protobuf.ProtobufUtil;
 import org.apache.hadoop.hbase.protobuf.generated.AuthenticationProtos;
 import org.apache.hadoop.hbase.protobuf.generated.RPCProtos.CellBlockMeta;
 import org.apache.hadoop.hbase.protobuf.generated.RPCProtos.ConnectionHeader;
@@ -272,7 +273,7 @@ public class RpcClient {
     @Override
     public String toString() {
       return "callId: " + this.id + " methodName: " + this.md.getName() + " param {" +
-        (this.param != null? TextFormat.shortDebugString(this.param): "") + "}";
+        (this.param != null? ProtobufUtil.getShortTextFormat(this.param): "") + "}";
     }
 
     /** Indicate when the call is complete and the

hbase-client/src/main/java/org/apache/hadoop/hbase/protobuf/ProtobufUtil.java

@@ -95,6 +95,7 @@ import org.apache.hadoop.hbase.protobuf.generated.ClientProtos.MutationProto.Col
 import org.apache.hadoop.hbase.protobuf.generated.ClientProtos.MutationProto.ColumnValue.QualifierValue;
 import org.apache.hadoop.hbase.protobuf.generated.ClientProtos.MutationProto.DeleteType;
 import org.apache.hadoop.hbase.protobuf.generated.ClientProtos.MutationProto.MutationType;
+import org.apache.hadoop.hbase.protobuf.generated.ClientProtos.ScanRequest;
 import org.apache.hadoop.hbase.protobuf.generated.ComparatorProtos;
 import org.apache.hadoop.hbase.protobuf.generated.HBaseProtos;
 import org.apache.hadoop.hbase.protobuf.generated.HBaseProtos.NameBytesPair;
@@ -106,6 +107,8 @@ import org.apache.hadoop.hbase.protobuf.generated.MapReduceProtos;
 import org.apache.hadoop.hbase.protobuf.generated.MasterAdminProtos.CreateTableRequest;
 import org.apache.hadoop.hbase.protobuf.generated.MasterAdminProtos.MasterAdminService;
 import org.apache.hadoop.hbase.protobuf.generated.MasterMonitorProtos.GetTableDescriptorsResponse;
+import org.apache.hadoop.hbase.protobuf.generated.RegionServerStatusProtos.RegionServerReportRequest;
+import org.apache.hadoop.hbase.protobuf.generated.RegionServerStatusProtos.RegionServerStartupRequest;
 import org.apache.hadoop.hbase.protobuf.generated.WALProtos.CompactionDescriptor;
 import org.apache.hadoop.hbase.security.access.Permission;
 import org.apache.hadoop.hbase.security.access.TablePermission;
@@ -434,12 +437,12 @@ public final class ProtobufUtil {
       // The proto has metadata only and the data is separate to be found in the cellScanner.
       if (cellScanner == null) {
         throw new DoNotRetryIOException("Cell count of " + cellCount + " but no cellScanner: " +
-          TextFormat.shortDebugString(proto));
+            toShortString(proto));
       }
       for (int i = 0; i < cellCount; i++) {
         if (!cellScanner.advance()) {
           throw new DoNotRetryIOException("Cell count of " + cellCount + " but at index " + i +
-            " no cell returned: " + TextFormat.shortDebugString(proto));
+            " no cell returned: " + toShortString(proto));
         }
         Cell cell = cellScanner.current();
         if (put == null) {
@@ -508,11 +511,13 @@ public final class ProtobufUtil {
     if (cellCount > 0) {
       // The proto has metadata only and the data is separate to be found in the cellScanner.
       if (cellScanner == null) {
+        // TextFormat should be fine for a Delete since it carries no data, just coordinates.
         throw new DoNotRetryIOException("Cell count of " + cellCount + " but no cellScanner: " +
           TextFormat.shortDebugString(proto));
       }
       for (int i = 0; i < cellCount; i++) {
         if (!cellScanner.advance()) {
+          // TextFormat should be fine for a Delete since it carries no data, just coordinates.
           throw new DoNotRetryIOException("Cell count of " + cellCount + " but at index " + i +
             " no cell returned: " + TextFormat.shortDebugString(proto));
         }
@@ -572,12 +577,12 @@ public final class ProtobufUtil {
       // The proto has metadata only and the data is separate to be found in the cellScanner.
       if (cellScanner == null) {
         throw new DoNotRetryIOException("Cell count of " + cellCount + " but no cellScanner: " +
-          TextFormat.shortDebugString(proto));
+          toShortString(proto));
       }
       for (int i = 0; i < cellCount; i++) {
         if (!cellScanner.advance()) {
           throw new DoNotRetryIOException("Cell count of " + cellCount + " but at index " + i +
-            " no cell returned: " + TextFormat.shortDebugString(proto));
+            " no cell returned: " + toShortString(proto));
         }
         Cell cell = cellScanner.current();
         if (append == null) {
@@ -2025,4 +2030,40 @@ public final class ProtobufUtil {
     }
     return builder.build();
   }
+
+  /**
+   * Return short version of Message toString'd, shorter than TextFormat#shortDebugString.
+   * Tries to NOT print out data both because it can be big but also so we do not have data in our
+   * logs. Use judiciously.
+   * @param m
+   * @return toString of passed <code>m</code>
+   */
+  public static String getShortTextFormat(Message m) {
+    if (m == null) return "null";
+    if (m instanceof ScanRequest) {
+      // This should be small and safe to output.  No data.
+      return TextFormat.shortDebugString(m);
+    } else if (m instanceof RegionServerReportRequest) {
+      // Print a short message only, just the servername and the requests, not the full load.
+      RegionServerReportRequest r = (RegionServerReportRequest)m;
+      return "server " + TextFormat.shortDebugString(r.getServer()) +
+        " load { numberOfRequests: " + r.getLoad().getNumberOfRequests() + " }";
+    } else if (m instanceof RegionServerStartupRequest) {
+      // Should be small enough.
+      return TextFormat.shortDebugString(m);
+    } else if (m instanceof MutationProto) {
+      return toShortString((MutationProto)m);
+    }
+    return "TODO: " + m.getClass().toString();
+  }
+
+  /**
+   * Print out some subset of a MutationProto rather than all of it and its data
+   * @param proto Protobuf to print out
+   * @return Short String of mutation proto
+   */
+  static String toShortString(final MutationProto proto) {
+    return "row=" + Bytes.toString(proto.getRow().toByteArray()) +
+        ", type=" + proto.getMutateType().toString();
+  }
 }

hbase-server/src/main/java/org/apache/hadoop/hbase/ipc/RpcServer.java

@@ -78,6 +78,7 @@ import org.apache.hadoop.hbase.exceptions.ServerNotRunningYetException;
 import org.apache.hadoop.hbase.io.ByteBufferOutputStream;
 import org.apache.hadoop.hbase.monitoring.MonitoredRPCHandler;
 import org.apache.hadoop.hbase.monitoring.TaskMonitor;
+import org.apache.hadoop.hbase.protobuf.ProtobufUtil;
 import org.apache.hadoop.hbase.protobuf.generated.RPCProtos.CellBlockMeta;
 import org.apache.hadoop.hbase.protobuf.generated.RPCProtos.ConnectionHeader;
 import org.apache.hadoop.hbase.protobuf.generated.RPCProtos.ExceptionResponse;
@@ -290,14 +291,32 @@ public class RpcServer implements RpcServerInterface {
 
     @Override
     public String toString() {
-      String serviceName = this.connection.service != null?
+      return toShortString() + " param: " +
-        this.connection.service.getDescriptorForType().getName(): "null";
+        (this.param != null? ProtobufUtil.getShortTextFormat(this.param): "") +
-      return "callId: " + this.id + " service: " + serviceName + " methodName: " +
-        ((this.md != null)? this.md.getName(): null) + " param: " +
-        (this.param != null? IPCUtil.getRequestShortTextFormat(this.param): "") +
         " connection: " + connection.toString();
     }
 
+    /*
+     * Short string representation without param info because param itself could be huge depends on
+     * the payload of a command
+     */
+    String toShortString() {
+      String serviceName = this.connection.service != null?
+        this.connection.service.getDescriptorForType().getName() : "null";
+      StringBuilder sb = new StringBuilder();
+      sb.append("callId: ");
+      sb.append(this.id);
+      sb.append(" service: ");
+      sb.append(serviceName);
+      sb.append(" methodName: ");
+      sb.append((this.md != null) ? this.md.getName() : "");
+      sb.append(" size: ");
+      sb.append(StringUtils.humanReadableInt(this.size));
+      sb.append(" connection: ");
+      sb.append(connection.toString());
+      return sb.toString();
+    }
+
     protected synchronized void setSaslTokenResponse(ByteBuffer response) {
       this.response = response;
     }
@@ -978,7 +997,7 @@ public class RpcServer implements RpcServerInterface {
                 done = true;
             }
             if (LOG.isDebugEnabled()) {
-              LOG.debug(getName() + call.toString() + " partially sent, wrote " +
+              LOG.debug(getName() + call.toShortString() + " partially sent, wrote " +
                 numBytes + " bytes.");
             }
           }
@@ -986,7 +1005,7 @@ public class RpcServer implements RpcServerInterface {
         }
       } finally {
         if (error && call != null) {
-          LOG.warn(getName() + call.toString() + ": output error");
+          LOG.warn(getName() + call.toShortString() + ": output error");
           done = true;               // error. no more data for this channel.
           closeConnection(call.connection);
         }
@@ -1787,7 +1806,7 @@ public class RpcServer implements RpcServerInterface {
           status.setConnection(call.connection.getHostAddress(), call.connection.getRemotePort());
           if (LOG.isDebugEnabled()) {
             UserGroupInformation remoteUser = call.connection.user;
-            LOG.debug(call.toString() + " executing as " +
+            LOG.debug(call.toShortString() + " executing as " +
               ((remoteUser == null)? "NULL principal": remoteUser.getUserName()));
           }
           Throwable errorThrowable = null;
@@ -1801,7 +1820,7 @@ public class RpcServer implements RpcServerInterface {
             }
             if (call.tinfo != null) {
               currentRequestSpan = Trace.startSpan(
-                  "handling " + call.toString(), call.tinfo, Sampler.ALWAYS);
+                  "handling " + call.toShortString(), call.tinfo, Sampler.ALWAYS);
             }
             RequestContext.set(User.create(call.connection.user), getRemoteIp(),
               call.connection.service);
@@ -1810,7 +1829,7 @@ public class RpcServer implements RpcServerInterface {
             resultPair = call(call.service, call.md, call.param, call.cellScanner, call.timestamp,
               status);
           } catch (Throwable e) {
-            LOG.debug(getName() + ": " + call.toString(), e);
+            LOG.debug(getName() + ": " + call.toShortString(), e);
             errorThrowable = e;
             error = StringUtils.stringifyException(e);
           } finally {

hbase-server/src/main/java/org/apache/hadoop/hbase/regionserver/QosFunction.java

@@ -158,7 +158,7 @@ class QosFunction implements Function<Pair<RequestHeader, Message>, Integer> {
         HRegion region = hRegionServer.getRegion(regionSpecifier);
         if (region.getRegionInfo().isMetaTable()) {
           if (LOG.isTraceEnabled()) {
-            LOG.trace("High priority: " + TextFormat.shortDebugString(param));
+            LOG.trace("High priority because region=" + region.getRegionNameAsString());
           }
           return HConstants.HIGH_QOS;
         }
@@ -178,14 +178,12 @@ class QosFunction implements Function<Pair<RequestHeader, Message>, Integer> {
       RegionScanner scanner = hRegionServer.getScanner(request.getScannerId());
       if (scanner != null && scanner.getRegionInfo().isMetaRegion()) {
         if (LOG.isTraceEnabled()) {
-          LOG.trace("High priority scanner request: " + TextFormat.shortDebugString(request));
+          // Scanner requests are small in size so TextFormat version should not overwhelm log.
+          LOG.trace("High priority scanner request " + TextFormat.shortDebugString(request));
         }
         return HConstants.HIGH_QOS;
       }
     }
-    if (LOG.isTraceEnabled()) {
-      LOG.trace("Low priority: " + TextFormat.shortDebugString(param));
-    }
     return HConstants.NORMAL_QOS;
   }