Author: stack Date: Fri May 24 22:05:56 2013 New Revision: 1486233 URL: http://svn.apache.org/r1486233 Log: HBASE-8366 HBaseServer logs the full query
Modified: hbase/branches/0.95/hbase-client/src/main/java/org/apache/hadoop/hbase/ipc/IPCUtil.java hbase/branches/0.95/hbase-client/src/main/java/org/apache/hadoop/hbase/ipc/RpcClient.java hbase/branches/0.95/hbase-client/src/main/java/org/apache/hadoop/hbase/protobuf/ProtobufUtil.java hbase/branches/0.95/hbase-server/src/main/java/org/apache/hadoop/hbase/ipc/RpcServer.java hbase/branches/0.95/hbase-server/src/main/java/org/apache/hadoop/hbase/regionserver/QosFunction.java Modified: hbase/branches/0.95/hbase-client/src/main/java/org/apache/hadoop/hbase/ipc/IPCUtil.java URL: http://svn.apache.org/viewvc/hbase/branches/0.95/hbase-client/src/main/java/org/apache/hadoop/hbase/ipc/IPCUtil.java?rev=1486233&r1=1486232&r2=1486233&view=diff ============================================================================== --- hbase/branches/0.95/hbase-client/src/main/java/org/apache/hadoop/hbase/ipc/IPCUtil.java (original) +++ hbase/branches/0.95/hbase-client/src/main/java/org/apache/hadoop/hbase/ipc/IPCUtil.java Fri May 24 22:05:56 2013 @@ -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); - } } \ No newline at end of file Modified: hbase/branches/0.95/hbase-client/src/main/java/org/apache/hadoop/hbase/ipc/RpcClient.java URL: http://svn.apache.org/viewvc/hbase/branches/0.95/hbase-client/src/main/java/org/apache/hadoop/hbase/ipc/RpcClient.java?rev=1486233&r1=1486232&r2=1486233&view=diff ============================================================================== --- hbase/branches/0.95/hbase-client/src/main/java/org/apache/hadoop/hbase/ipc/RpcClient.java (original) +++ hbase/branches/0.95/hbase-client/src/main/java/org/apache/hadoop/hbase/ipc/RpcClient.java Fri May 24 22:05:56 2013 @@ -57,6 +57,7 @@ import org.apache.hadoop.hbase.HConstant 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 Modified: hbase/branches/0.95/hbase-client/src/main/java/org/apache/hadoop/hbase/protobuf/ProtobufUtil.java URL: http://svn.apache.org/viewvc/hbase/branches/0.95/hbase-client/src/main/java/org/apache/hadoop/hbase/protobuf/ProtobufUtil.java?rev=1486233&r1=1486232&r2=1486233&view=diff ============================================================================== --- hbase/branches/0.95/hbase-client/src/main/java/org/apache/hadoop/hbase/protobuf/ProtobufUtil.java (original) +++ hbase/branches/0.95/hbase-client/src/main/java/org/apache/hadoop/hbase/protobuf/ProtobufUtil.java Fri May 24 22:05:56 2013 @@ -95,6 +95,7 @@ import org.apache.hadoop.hbase.protobuf. 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. 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(); + } } Modified: hbase/branches/0.95/hbase-server/src/main/java/org/apache/hadoop/hbase/ipc/RpcServer.java URL: http://svn.apache.org/viewvc/hbase/branches/0.95/hbase-server/src/main/java/org/apache/hadoop/hbase/ipc/RpcServer.java?rev=1486233&r1=1486232&r2=1486233&view=diff ============================================================================== --- hbase/branches/0.95/hbase-server/src/main/java/org/apache/hadoop/hbase/ipc/RpcServer.java (original) +++ hbase/branches/0.95/hbase-server/src/main/java/org/apache/hadoop/hbase/ipc/RpcServer.java Fri May 24 22:05:56 2013 @@ -78,6 +78,7 @@ import org.apache.hadoop.hbase.exception 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 RpcSer @Override public String toString() { - String serviceName = this.connection.service != null? - this.connection.service.getDescriptorForType().getName(): "null"; - return "callId: " + this.id + " service: " + serviceName + " methodName: " + - ((this.md != null)? this.md.getName(): null) + " param: " + - (this.param != null? IPCUtil.getRequestShortTextFormat(this.param): "") + + return toShortString() + " param: " + + (this.param != null? ProtobufUtil.getShortTextFormat(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 RpcSer 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 RpcSer } } 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 RpcSer 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 RpcSer } 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 RpcSer 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 { Modified: hbase/branches/0.95/hbase-server/src/main/java/org/apache/hadoop/hbase/regionserver/QosFunction.java URL: http://svn.apache.org/viewvc/hbase/branches/0.95/hbase-server/src/main/java/org/apache/hadoop/hbase/regionserver/QosFunction.java?rev=1486233&r1=1486232&r2=1486233&view=diff ============================================================================== --- hbase/branches/0.95/hbase-server/src/main/java/org/apache/hadoop/hbase/regionserver/QosFunction.java (original) +++ hbase/branches/0.95/hbase-server/src/main/java/org/apache/hadoop/hbase/regionserver/QosFunction.java Fri May 24 22:05:56 2013 @@ -158,7 +158,7 @@ class QosFunction implements Function<Pa 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<Pa 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; }