From 69756da503f4b1bc74462f67c65124cab5d045fb Mon Sep 17 00:00:00 2001 From: "krish.dey" Date: Tue, 28 Aug 2018 10:49:10 -0400 Subject: [PATCH] HBASE-20942 Fix ArrayIndexOutOfBoundsException for RpcServer TRACE logging Also makes the trace log message length configurable. Signed-off-by: Josh Elser --- .../apache/hadoop/hbase/ipc/RpcServer.java | 25 ++++- .../hbase/ipc/TestRpcServerTraceLogging.java | 95 +++++++++++++++++++ 2 files changed, 118 insertions(+), 2 deletions(-) create mode 100644 hbase-server/src/test/java/org/apache/hadoop/hbase/ipc/TestRpcServerTraceLogging.java diff --git a/hbase-server/src/main/java/org/apache/hadoop/hbase/ipc/RpcServer.java b/hbase-server/src/main/java/org/apache/hadoop/hbase/ipc/RpcServer.java index fb2ee4040c2..0207b0316d4 100644 --- a/hbase-server/src/main/java/org/apache/hadoop/hbase/ipc/RpcServer.java +++ b/hbase-server/src/main/java/org/apache/hadoop/hbase/ipc/RpcServer.java @@ -191,6 +191,10 @@ public abstract class RpcServer implements RpcServerInterface, protected static final int DEFAULT_WARN_RESPONSE_TIME = 10000; // milliseconds protected static final int DEFAULT_WARN_RESPONSE_SIZE = 100 * 1024 * 1024; + protected static final int DEFAULT_TRACE_LOG_MAX_LENGTH = 1000; + protected static final String TRACE_LOG_MAX_LENGTH = "hbase.ipc.trace.log.max.length"; + protected static final String KEY_WORD_TRUNCATED = " "; + protected static final ObjectMapper MAPPER = new ObjectMapper(); protected final int maxRequestSize; @@ -500,8 +504,7 @@ public abstract class RpcServer implements RpcServerInterface, String stringifiedParam = ProtobufUtil.getShortTextFormat(param); if (stringifiedParam.length() > 150) { // Truncate to 1000 chars if TRACE is on, else to 150 chars - stringifiedParam = stringifiedParam.subSequence( - 0, LOG.isTraceEnabled() ? 1000 : 150) + " "; + stringifiedParam = truncateTraceLog(stringifiedParam); } responseInfo.put("param", stringifiedParam); if (param instanceof ClientProtos.ScanRequest && rsRpcServices != null) { @@ -517,6 +520,24 @@ public abstract class RpcServer implements RpcServerInterface, LOG.warn("(response" + tag + "): " + MAPPER.writeValueAsString(responseInfo)); } + /** + * Truncate to number of chars decided by conf hbase.ipc.trace.log.max.length + * if TRACE is on else to 150 chars Refer to Jira HBASE-20826 and HBASE-20942 + * @param strParam stringifiedParam to be truncated + * @return truncated trace log string + */ + @VisibleForTesting + String truncateTraceLog(String strParam) { + if (LOG.isTraceEnabled()) { + int traceLogMaxLength = getConf().getInt(TRACE_LOG_MAX_LENGTH, DEFAULT_TRACE_LOG_MAX_LENGTH); + int truncatedLength = + strParam.length() < traceLogMaxLength ? strParam.length() : traceLogMaxLength; + String truncatedFlag = truncatedLength == strParam.length() ? "" : KEY_WORD_TRUNCATED; + return strParam.subSequence(0, truncatedLength) + truncatedFlag; + } + return strParam.subSequence(0, 150) + KEY_WORD_TRUNCATED; + } + /** * Set the handler for calling out of RPC for error conditions. * @param handler the handler implementation diff --git a/hbase-server/src/test/java/org/apache/hadoop/hbase/ipc/TestRpcServerTraceLogging.java b/hbase-server/src/test/java/org/apache/hadoop/hbase/ipc/TestRpcServerTraceLogging.java new file mode 100644 index 00000000000..e95c88ce4f5 --- /dev/null +++ b/hbase-server/src/test/java/org/apache/hadoop/hbase/ipc/TestRpcServerTraceLogging.java @@ -0,0 +1,95 @@ +/** + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF licenses this file + * to you under the Apache License, Version 2.0 (the + * "License"); you may not use this file except in compliance + * with the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package org.apache.hadoop.hbase.ipc; + +import static org.junit.Assert.assertEquals; +import static org.junit.Assert.assertFalse; +import static org.junit.Assert.assertTrue; + +import org.apache.hadoop.conf.Configuration; +import org.apache.hadoop.hbase.HBaseClassTestRule; +import org.apache.hadoop.hbase.testclassification.SmallTests; +import org.apache.log4j.Level; +import org.apache.log4j.Logger; +import org.junit.BeforeClass; +import org.junit.ClassRule; +import org.junit.Test; +import org.junit.experimental.categories.Category; +import org.mockito.Mockito; + + +@Category(SmallTests.class) +public class TestRpcServerTraceLogging { + + @ClassRule + public static final HBaseClassTestRule CLASS_RULE = HBaseClassTestRule + .forClass(TestRpcServerTraceLogging.class); + + static Logger rpcServerLog = Logger.getLogger(RpcServer.class); + + static final String TRACE_LOG_MSG = + "This is dummy message for testing:: region { type: REGION_NAME value: \"hbase:meta,,1\" }" + + " scan { column { family: \"info\" } time_range { from: 0 to: 9223372036854775807 } " + + "max_versions: 1 cache_blocks: true max_result_size: 2097152 caching: 2147483647 } " + + "number_of_rows: 2147483647 close_scanner: false client_handles_partials: " + + "true client_handles_heartbeats: true track_scan_metrics: false"; + + static final int TRACE_LOG_LENGTH = TRACE_LOG_MSG.length(); + + static final RpcServer mockRpcServer = Mockito.mock(RpcServer.class); + + static final Configuration conf = new Configuration(false); + + @BeforeClass + public static void setUp() { + Mockito.when(mockRpcServer.getConf()).thenReturn(conf); + Mockito.when(mockRpcServer.truncateTraceLog(Mockito.any(String.class))).thenCallRealMethod(); + } + + @Test + public void testLoggingWithTraceOff() { + conf.setInt("hbase.ipc.trace.log.max.length", 250); + rpcServerLog.setLevel(Level.DEBUG); + String truncatedString = mockRpcServer.truncateTraceLog(TRACE_LOG_MSG); + + assertEquals(150 + RpcServer.KEY_WORD_TRUNCATED.length(), truncatedString.length()); + assertTrue(truncatedString.contains(RpcServer.KEY_WORD_TRUNCATED)); + } + + @Test + public void testLoggingWithTraceOn() { + conf.setInt("hbase.ipc.trace.log.max.length", 250); + rpcServerLog.setLevel(Level.TRACE); + String truncatedString = mockRpcServer.truncateTraceLog(TRACE_LOG_MSG); + + assertEquals(250 + RpcServer.KEY_WORD_TRUNCATED.length(), truncatedString.length()); + assertTrue(truncatedString.contains(RpcServer.KEY_WORD_TRUNCATED)); + } + + @Test + public void testLoggingWithTraceOnLargeMax() { + conf.setInt("hbase.ipc.trace.log.max.length", 2000); + rpcServerLog.setLevel(Level.TRACE); + String truncatedString = mockRpcServer.truncateTraceLog(TRACE_LOG_MSG); + + assertEquals(TRACE_LOG_LENGTH, truncatedString.length()); + assertFalse( + mockRpcServer.truncateTraceLog(TRACE_LOG_MSG).contains(RpcServer.KEY_WORD_TRUNCATED)); + } +}