HBASE-20942 Fix ArrayIndexOutOfBoundsException for RpcServer TRACE logging

Also makes the trace log message length configurable.

Signed-off-by: Josh Elser <elserj@apache.org>
This commit is contained in:
krish.dey 2018-08-28 10:49:10 -04:00 committed by Duo Zhang
parent 2c19b04274
commit 69756da503
2 changed files with 118 additions and 2 deletions

View File

@ -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 = " <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) + " <TRUNCATED>";
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

View File

@ -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));
}
}