Skip to content

HBASE-23381: Improve Logging in HBase Commons Package #913

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
wants to merge 3 commits into from
Closed

HBASE-23381: Improve Logging in HBase Commons Package #913

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
09d1449
HBASE-23381: Improve Logging in HBase Commons Package
belugabehr Dec 6, 2019
8d423ee
Merge branch 'master' into HBASE-23381
belugabehr Dec 30, 2019
2e30644
Merge branch 'master' into HBASE-23381
belugabehr Feb 6, 2020
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
68 changes: 23 additions & 45 deletions hbase-common/src/main/java/org/apache/hadoop/hbase/ChoreService.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -20,8 +20,6 @@

import java.util.ArrayList;
import java.util.HashMap;
import java.util.LinkedHashMap;
import java.util.Map.Entry;
import java.util.concurrent.ScheduledFuture;
import java.util.concurrent.ScheduledThreadPoolExecutor;
import java.util.concurrent.ThreadFactory;
Expand Down Expand Up @@ -151,20 +149,18 @@ public synchronized boolean scheduleChore(ScheduledChore chore) {

try {
if (chore.getPeriod() <= 0) {
LOG.info("Chore {} is disabled because its period is not positive.", chore);
LOG.info("Chore {} is disabled because its period is not positive", chore);
return false;
}
LOG.info("Chore {} is enabled.", chore);
LOG.info("Chore {} is enabled", chore);
chore.setChoreServicer(this);
ScheduledFuture<?> future =
scheduler.scheduleAtFixedRate(chore, chore.getInitialDelay(), chore.getPeriod(),
chore.getTimeUnit());
scheduledChores.put(chore, future);
return true;
} catch (Exception exception) {
if (LOG.isInfoEnabled()) {
LOG.info("Could not successfully schedule chore: " + chore.getName());
}
} catch (Exception ex) {
LOG.error("Could not successfully schedule chore: {}", chore, ex);
return false;
}
}
Expand Down Expand Up @@ -280,7 +276,12 @@ private synchronized boolean requestCorePoolIncrease() {
// amongst occurrences of the same chore).
if (scheduler.getCorePoolSize() < scheduledChores.size()) {
scheduler.setCorePoolSize(scheduler.getCorePoolSize() + 1);
printChoreServiceDetails("requestCorePoolIncrease");

LOG.trace("requestCorePoolIncrease");
LOG.trace("ChoreService corePoolSize: {}", getCorePoolSize());
LOG.trace("ChoreService scheduledChores: {}", getNumberOfScheduledChores());
LOG.trace("ChoreService missingStartTimeCount: {}", getNumberOfChoresMissingStartTime());

return true;
}
return false;
Expand All @@ -294,7 +295,11 @@ private synchronized boolean requestCorePoolIncrease() {
private synchronized void requestCorePoolDecrease() {
if (scheduler.getCorePoolSize() > MIN_CORE_POOL_SIZE) {
scheduler.setCorePoolSize(scheduler.getCorePoolSize() - 1);
printChoreServiceDetails("requestCorePoolDecrease");

LOG.trace("requestCorePoolDecrease");
LOG.trace("ChoreService corePoolSize: {}", getCorePoolSize());
LOG.trace("ChoreService scheduledChores: {}", getNumberOfScheduledChores());
LOG.trace("ChoreService missingStartTimeCount: {}", getNumberOfChoresMissingStartTime());
}
}

Expand All @@ -315,7 +320,12 @@ public synchronized void onChoreMissedStartTime(ScheduledChore chore) {
// more on each iteration. This hurts us because the ScheduledThreadPoolExecutor allocates
// idle threads to chores based on how delayed they are.
rescheduleChore(chore);
printChoreDetails("onChoreMissedStartTime", chore);

if (LOG.isTraceEnabled()) {
LOG.trace("onChoreMissedStartTime");
LOG.trace("Chore: {}", chore);
LOG.trace("Chore timeBetweenRuns: {}", chore.getTimeBetweenRuns());
}
}

/**
Expand All @@ -325,10 +335,8 @@ public synchronized void onChoreMissedStartTime(ScheduledChore chore) {
*/
public synchronized void shutdown() {
scheduler.shutdownNow();
if (LOG.isInfoEnabled()) {
LOG.info("Chore service for: " + coreThreadPoolPrefix + " had " + scheduledChores.keySet()
+ " on shutdown");
}
LOG.info("Chore service for: {} had {} on shutdown", coreThreadPoolPrefix,
scheduledChores.keySet());
cancelAllChores(true);
scheduledChores.clear();
choresMissingStartTime.clear();
Expand Down Expand Up @@ -359,34 +367,4 @@ private void cancelAllChores(final boolean mayInterruptIfRunning) {
}
}

/**
* Prints a summary of important details about the chore. Used for debugging purposes
*/
private void printChoreDetails(final String header, ScheduledChore chore) {
LinkedHashMap<String, String> output = new LinkedHashMap<>();
output.put(header, "");
output.put("Chore name: ", chore.getName());
output.put("Chore period: ", Integer.toString(chore.getPeriod()));
output.put("Chore timeBetweenRuns: ", Long.toString(chore.getTimeBetweenRuns()));

for (Entry<String, String> entry : output.entrySet()) {
if (LOG.isTraceEnabled()) LOG.trace(entry.getKey() + entry.getValue());
}
}

/**
* Prints a summary of important details about the service. Used for debugging purposes
*/
private void printChoreServiceDetails(final String header) {
LinkedHashMap<String, String> output = new LinkedHashMap<>();
output.put(header, "");
output.put("ChoreService corePoolSize: ", Integer.toString(getCorePoolSize()));
output.put("ChoreService scheduledChores: ", Integer.toString(getNumberOfScheduledChores()));
output.put("ChoreService missingStartTimeCount: ",
Integer.toString(getNumberOfChoresMissingStartTime()));

for (Entry<String, String> entry : output.entrySet()) {
if (LOG.isTraceEnabled()) LOG.trace(entry.getKey() + entry.getValue());
}
}
}
25 changes: 9 additions & 16 deletions hbase-common/src/main/java/org/apache/hadoop/hbase/HBaseConfiguration.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -165,7 +165,7 @@ public static boolean isShowConfInServlet() {
}
} catch (LinkageError e) {
// should we handle it more aggressively in addition to log the error?
LOG.warn("Error thrown: ", e);
LOG.warn("Failed to load ConfServlet", e);
} catch (ClassNotFoundException ce) {
LOG.debug("ClassNotFound: ConfServlet");
// ignore
Expand All @@ -191,29 +191,22 @@ public static String getPassword(Configuration conf, String alias,
Method m = Configuration.class.getMethod("getPassword", String.class);
char[] p = (char[]) m.invoke(conf, alias);
if (p != null) {
LOG.debug(String.format("Config option \"%s\" was found through" +
" the Configuration getPassword method.", alias));
LOG.debug(
"Config option \"{}\" was found through the Configuration getPassword method",
alias);
passwd = new String(p);
} else {
LOG.debug(String.format(
"Config option \"%s\" was not found. Using provided default value",
alias));
LOG.debug("Config option \"{}\" was not found. Using provided default value", alias);
passwd = defPass;
}
} catch (NoSuchMethodException e) {
// this is a version of Hadoop where the credential
//provider API doesn't exist yet
LOG.debug(String.format(
"Credential.getPassword method is not available." +
" Falling back to configuration."));
LOG.debug("Credential.getPassword method is not available. Falling back to configuration",
e);
passwd = conf.get(alias, defPass);
} catch (SecurityException e) {
throw new IOException(e.getMessage(), e);
} catch (IllegalAccessException e) {
throw new IOException(e.getMessage(), e);
} catch (IllegalArgumentException e) {
throw new IOException(e.getMessage(), e);
} catch (InvocationTargetException e) {
} catch (SecurityException | IllegalAccessException | IllegalArgumentException
| InvocationTargetException e) {
throw new IOException(e.getMessage(), e);
}
return passwd;
Expand Down
120 changes: 38 additions & 82 deletions hbase-common/src/main/java/org/apache/hadoop/hbase/KeyValueUtil.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -35,8 +35,6 @@
import org.apache.hadoop.io.IOUtils;
import org.apache.hadoop.io.WritableUtils;
import org.apache.yetus.audience.InterfaceAudience;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

import org.apache.hbase.thirdparty.com.google.common.base.Function;
import org.apache.hbase.thirdparty.com.google.common.collect.Lists;
Expand All @@ -48,8 +46,6 @@
@InterfaceAudience.Private
public class KeyValueUtil {

private static final Logger LOG = LoggerFactory.getLogger(KeyValueUtil.class);
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'll have to review where we call these utility methods since we're pulling out all this logging.

Please no one merge this util someone has done that check.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Great. Thanks. This goes under the heading of 'log and throw'.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

that's well and good in principle but only works if we actually log something about the exception when it's eventually caught. also depending on the severity it might be needed if we're at risk of stacktrace optimization by the JVM and log rolling making it so we can't actually get details from here when it comes time to log the exception elsewhere.


/**************** length *********************/

public static int length(short rlen, byte flen, int qlen, int vlen, int tlen, boolean withTags) {
Expand Down Expand Up @@ -519,119 +515,89 @@ static String bytesToHex(byte[] buf, int offset, int length) {

static void checkKeyValueBytes(byte[] buf, int offset, int length, boolean withTags) {
if (buf == null) {
String msg = "Invalid to have null byte array in KeyValue.";
LOG.warn(msg);
throw new IllegalArgumentException(msg);
throw new IllegalArgumentException("Invalid to have null byte array in KeyValue.");
}

int pos = offset, endOffset = offset + length;
// check the key
if (pos + Bytes.SIZEOF_INT > endOffset) {
String msg =
"Overflow when reading key length at position=" + pos + bytesToHex(buf, offset, length);
LOG.warn(msg);
throw new IllegalArgumentException(msg);
throw new IllegalArgumentException(
"Overflow when reading key length at position=" + pos + bytesToHex(buf, offset, length));
}
int keyLen = Bytes.toInt(buf, pos, Bytes.SIZEOF_INT);
pos += Bytes.SIZEOF_INT;
if (keyLen <= 0 || pos + keyLen > endOffset) {
String msg =
"Invalid key length in KeyValue. keyLength=" + keyLen + bytesToHex(buf, offset, length);
LOG.warn(msg);
throw new IllegalArgumentException(msg);
throw new IllegalArgumentException("Invalid key length in KeyValue. keyLength=" + keyLen + bytesToHex(buf, offset, length));
}
// check the value
if (pos + Bytes.SIZEOF_INT > endOffset) {
String msg =
"Overflow when reading value length at position=" + pos + bytesToHex(buf, offset, length);
LOG.warn(msg);
throw new IllegalArgumentException(msg);
throw new IllegalArgumentException("Overflow when reading value length at position=" + pos
+ bytesToHex(buf, offset, length));
}
int valLen = Bytes.toInt(buf, pos, Bytes.SIZEOF_INT);
pos += Bytes.SIZEOF_INT;
if (valLen < 0 || pos + valLen > endOffset) {
String msg = "Invalid value length in KeyValue, valueLength=" + valLen +
bytesToHex(buf, offset, length);
LOG.warn(msg);
throw new IllegalArgumentException(msg);
throw new IllegalArgumentException("Invalid value length in KeyValue, valueLength=" + valLen
+ bytesToHex(buf, offset, length));
}
// check the row
if (pos + Bytes.SIZEOF_SHORT > endOffset) {
String msg =
"Overflow when reading row length at position=" + pos + bytesToHex(buf, offset, length);
LOG.warn(msg);
throw new IllegalArgumentException(msg);
throw new IllegalArgumentException(
"Overflow when reading row length at position=" + pos + bytesToHex(buf, offset, length));
}
short rowLen = Bytes.toShort(buf, pos, Bytes.SIZEOF_SHORT);
pos += Bytes.SIZEOF_SHORT;
if (rowLen < 0 || pos + rowLen > endOffset) {
String msg =
"Invalid row length in KeyValue, rowLength=" + rowLen + bytesToHex(buf, offset, length);
LOG.warn(msg);
throw new IllegalArgumentException(msg);
throw new IllegalArgumentException(
"Invalid row length in KeyValue, rowLength=" + rowLen + bytesToHex(buf, offset, length));
}
pos += rowLen;
// check the family
if (pos + Bytes.SIZEOF_BYTE > endOffset) {
String msg = "Overflow when reading family length at position=" + pos +
bytesToHex(buf, offset, length);
LOG.warn(msg);
throw new IllegalArgumentException(msg);
throw new IllegalArgumentException("Overflow when reading family length at position=" + pos
+ bytesToHex(buf, offset, length));
}
int familyLen = buf[pos];
pos += Bytes.SIZEOF_BYTE;
if (familyLen < 0 || pos + familyLen > endOffset) {
String msg = "Invalid family length in KeyValue, familyLength=" + familyLen +
bytesToHex(buf, offset, length);
LOG.warn(msg);
throw new IllegalArgumentException(msg);
throw new IllegalArgumentException("Invalid family length in KeyValue, familyLength="
+ familyLen + bytesToHex(buf, offset, length));
}
pos += familyLen;
// check the qualifier
int qualifierLen = keyLen - Bytes.SIZEOF_SHORT - rowLen - Bytes.SIZEOF_BYTE - familyLen
- Bytes.SIZEOF_LONG - Bytes.SIZEOF_BYTE;
if (qualifierLen < 0 || pos + qualifierLen > endOffset) {
String msg = "Invalid qualifier length in KeyValue, qualifierLen=" + qualifierLen +
bytesToHex(buf, offset, length);
LOG.warn(msg);
throw new IllegalArgumentException(msg);
throw new IllegalArgumentException("Invalid qualifier length in KeyValue, qualifierLen=" + qualifierLen +
bytesToHex(buf, offset, length));
}
pos += qualifierLen;
// check the timestamp
if (pos + Bytes.SIZEOF_LONG > endOffset) {
String msg =
"Overflow when reading timestamp at position=" + pos + bytesToHex(buf, offset, length);
LOG.warn(msg);
throw new IllegalArgumentException(msg);
throw new IllegalArgumentException(
"Overflow when reading timestamp at position=" + pos + bytesToHex(buf, offset, length));
}
long timestamp = Bytes.toLong(buf, pos, Bytes.SIZEOF_LONG);
if (timestamp < 0) {
String msg =
"Timestamp cannot be negative, ts=" + timestamp + bytesToHex(buf, offset, length);
LOG.warn(msg);
throw new IllegalArgumentException(msg);
throw new IllegalArgumentException(
"Timestamp cannot be negative, ts=" + timestamp + bytesToHex(buf, offset, length));
}
pos += Bytes.SIZEOF_LONG;
// check the type
if (pos + Bytes.SIZEOF_BYTE > endOffset) {
String msg =
"Overflow when reading type at position=" + pos + bytesToHex(buf, offset, length);
LOG.warn(msg);
throw new IllegalArgumentException(msg);
throw new IllegalArgumentException(
"Overflow when reading type at position=" + pos + bytesToHex(buf, offset, length));
}
byte type = buf[pos];
if (!Type.isValidType(type)) {
String msg = "Invalid type in KeyValue, type=" + type + bytesToHex(buf, offset, length);
LOG.warn(msg);
throw new IllegalArgumentException(msg);
throw new IllegalArgumentException(
"Invalid type in KeyValue, type=" + type + bytesToHex(buf, offset, length));
}
pos += Bytes.SIZEOF_BYTE;
// check the value
if (pos + valLen > endOffset) {
String msg =
"Overflow when reading value part at position=" + pos + bytesToHex(buf, offset, length);
LOG.warn(msg);
throw new IllegalArgumentException(msg);
throw new IllegalArgumentException(
"Overflow when reading value part at position=" + pos + bytesToHex(buf, offset, length));
}
pos += valLen;
// check the tags
Expand All @@ -643,46 +609,36 @@ static void checkKeyValueBytes(byte[] buf, int offset, int length, boolean withT
pos = checkKeyValueTagBytes(buf, offset, length, pos, endOffset);
}
if (pos != endOffset) {
String msg = "Some redundant bytes in KeyValue's buffer, startOffset=" + pos + ", endOffset="
+ endOffset + bytesToHex(buf, offset, length);
LOG.warn(msg);
throw new IllegalArgumentException(msg);
throw new IllegalArgumentException("Some redundant bytes in KeyValue's buffer, startOffset="
+ pos + ", endOffset=" + endOffset + bytesToHex(buf, offset, length));
}
}

private static int checkKeyValueTagBytes(byte[] buf, int offset, int length, int pos,
int endOffset) {
if (pos + Bytes.SIZEOF_SHORT > endOffset) {
String msg = "Overflow when reading tags length at position=" + pos +
bytesToHex(buf, offset, length);
LOG.warn(msg);
throw new IllegalArgumentException(msg);
throw new IllegalArgumentException(
"Overflow when reading tags length at position=" + pos + bytesToHex(buf, offset, length));
}
short tagsLen = Bytes.toShort(buf, pos);
pos += Bytes.SIZEOF_SHORT;
if (tagsLen < 0 || pos + tagsLen > endOffset) {
String msg = "Invalid tags length in KeyValue at position=" + (pos - Bytes.SIZEOF_SHORT)
+ bytesToHex(buf, offset, length);
LOG.warn(msg);
throw new IllegalArgumentException(msg);
throw new IllegalArgumentException("Invalid tags length in KeyValue at position="
+ (pos - Bytes.SIZEOF_SHORT) + bytesToHex(buf, offset, length));
}
int tagsEndOffset = pos + tagsLen;
for (; pos < tagsEndOffset;) {
if (pos + Tag.TAG_LENGTH_SIZE > endOffset) {
String msg = "Overflow when reading tag length at position=" + pos +
bytesToHex(buf, offset, length);
LOG.warn(msg);
throw new IllegalArgumentException(msg);
throw new IllegalArgumentException("Overflow when reading tag length at position=" + pos
+ bytesToHex(buf, offset, length));
}
short tagLen = Bytes.toShort(buf, pos);
pos += Tag.TAG_LENGTH_SIZE;
// tagLen contains one byte tag type, so must be not less than 1.
if (tagLen < 1 || pos + tagLen > endOffset) {
String msg =
throw new IllegalArgumentException(
"Invalid tag length at position=" + (pos - Tag.TAG_LENGTH_SIZE) + ", tagLength="
+ tagLen + bytesToHex(buf, offset, length);
LOG.warn(msg);
throw new IllegalArgumentException(msg);
+ tagLen + bytesToHex(buf, offset, length));
}
pos += tagLen;
}
Expand Down
Loading