NIFI-9871 Correct Component Stack Trace Logging (#5945)

- Refactored SimpleProcessLogger to avoid sending stack trace causes to SLF4J Logger
- Refactored SimpleProcessLogger to minimize duplication of component message formatting
- Updated ConnectableTask logging to avoid repeating Throwable class in message string
- Refactored TestSimpleProcessLogger to improve coverage and confirm consistent argument handling
- Corrected handling of exception strings in argument arrays
This commit is contained in:
exceptionfactory 2022-04-12 10:14:36 -05:00 committed by GitHub
parent 47f75651bb
commit 27e78c6f0c
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
3 changed files with 462 additions and 298 deletions

View File

@ -16,7 +16,7 @@
*/
package org.apache.nifi.processor;
import org.apache.commons.lang3.StringUtils;
import org.apache.commons.lang3.ArrayUtils;
import org.apache.nifi.logging.ComponentLog;
import org.apache.nifi.logging.LogLevel;
import org.apache.nifi.logging.LogMessage;
@ -32,6 +32,8 @@ public class SimpleProcessLogger implements ComponentLog {
private static final String CAUSED_BY = String.format("%n- Caused by: ");
private static final Throwable NULL_THROWABLE = null;
private final Logger logger;
private final LogRepository logRepository;
private final Object component;
@ -46,75 +48,62 @@ public class SimpleProcessLogger implements ComponentLog {
this.component = component;
}
private Object[] addProcessor(final Object[] originalArgs) {
return prependToArgs(originalArgs, component);
}
private Object[] prependToArgs(final Object[] originalArgs, final Object... toAdd) {
final Object[] newArgs = new Object[originalArgs.length + toAdd.length];
System.arraycopy(toAdd, 0, newArgs, 0, toAdd.length);
System.arraycopy(originalArgs, 0, newArgs, toAdd.length, originalArgs.length);
return newArgs;
}
private boolean lastArgIsException(final Object[] os) {
return (os != null && os.length > 0 && (os[os.length - 1] instanceof Throwable));
}
@Override
public void warn(String msg, final Throwable t) {
if (!isWarnEnabled()) {
return;
}
public void warn(final String msg, final Throwable t) {
if (isWarnEnabled()) {
final String componentMessage = getComponentMessage(msg);
final Object[] repositoryArguments = getRepositoryArguments(t);
msg = "{} " + msg;
final Object[] os = {component, getCauses(t), t};
logger.warn(msg, os);
logRepository.addLogMessage(LogLevel.WARN, msg, os, t);
}
@Override
public void warn(String msg, Object[] os) {
if (!isWarnEnabled()) {
return;
}
if (lastArgIsException(os)) {
warn(msg, os, (Throwable) os[os.length - 1]);
} else {
msg = "{} " + msg;
os = addProcessor(os);
logger.warn(msg, os);
logRepository.addLogMessage(LogLevel.WARN, msg, os);
if (t == null) {
logger.warn(componentMessage, component);
logRepository.addLogMessage(LogLevel.WARN, componentMessage, repositoryArguments);
} else {
logger.warn(componentMessage, component, t);
logRepository.addLogMessage(LogLevel.WARN, getCausesMessage(msg), repositoryArguments, t);
}
}
}
@Override
public void warn(String msg, Object[] os, final Throwable t) {
if (!isWarnEnabled()) {
return;
}
public void warn(final String msg, final Object[] os) {
if (isWarnEnabled()) {
final String componentMessage = getComponentMessage(msg);
final Object[] arguments = insertComponent(os);
os = addProcessorAndThrowable(os, t);
msg = "{} " + msg + ": {}";
logger.warn(msg, os);
logRepository.addLogMessage(LogLevel.WARN, msg, os, t);
final Throwable lastThrowable = findLastThrowable(os);
if (lastThrowable == null) {
logger.warn(componentMessage, arguments);
logRepository.addLogMessage(LogLevel.WARN, componentMessage, arguments);
} else {
logger.warn(componentMessage, setFormattedThrowable(arguments, lastThrowable));
logRepository.addLogMessage(LogLevel.WARN, getCausesMessage(msg), addCauses(arguments, lastThrowable), lastThrowable);
}
}
}
@Override
public void warn(String msg) {
if (!isWarnEnabled()) {
return;
}
public void warn(final String msg, final Object[] os, final Throwable t) {
if (isWarnEnabled()) {
final String componentMessage = getComponentMessage(msg);
final Object[] arguments = insertComponent(os);
msg = "{} " + msg;
final Object[] os = {component};
logger.warn(msg, component);
logRepository.addLogMessage(LogLevel.WARN, msg, os);
if (t == null) {
logger.warn(componentMessage, arguments);
logRepository.addLogMessage(LogLevel.WARN, componentMessage, arguments);
} else {
logger.warn(componentMessage, arguments, t);
logRepository.addLogMessage(LogLevel.WARN, getCausesMessage(msg), addCauses(arguments, t), t);
}
}
}
@Override
public void warn(LogMessage logMessage) {
public void warn(final String msg) {
warn(msg, NULL_THROWABLE);
}
@Override
public void warn(final LogMessage logMessage) {
if (isWarnEnabled()) {
log(LogLevel.WARN, logMessage);
logRepository.addLogMessage(logMessage);
@ -122,56 +111,61 @@ public class SimpleProcessLogger implements ComponentLog {
}
@Override
public void trace(String msg, Throwable t) {
if (!isTraceEnabled()) {
return;
}
public void trace(final String msg, final Throwable t) {
if (isTraceEnabled()) {
final String componentMessage = getComponentMessage(msg);
final Object[] repositoryArguments = getRepositoryArguments(t);
msg = "{} " + msg;
final Object[] os = {component, getCauses(t), t};
logger.trace(msg, os);
logRepository.addLogMessage(LogLevel.TRACE, msg, os, t);
if (t == null) {
logger.trace(componentMessage, component);
logRepository.addLogMessage(LogLevel.TRACE, componentMessage, repositoryArguments);
} else {
logger.trace(componentMessage, component, t);
logRepository.addLogMessage(LogLevel.TRACE, getCausesMessage(msg), repositoryArguments, t);
}
}
}
@Override
public void trace(String msg, Object[] os) {
if (!isTraceEnabled()) {
return;
}
public void trace(final String msg, final Object[] os) {
if (isTraceEnabled()) {
final String componentMessage = getComponentMessage(msg);
final Object[] arguments = insertComponent(os);
msg = "{} " + msg;
os = addProcessor(os);
logger.trace(msg, os);
logRepository.addLogMessage(LogLevel.TRACE, msg, os);
final Throwable lastThrowable = findLastThrowable(os);
if (lastThrowable == null) {
logger.trace(componentMessage, arguments);
logRepository.addLogMessage(LogLevel.TRACE, componentMessage, arguments);
} else {
logger.trace(componentMessage, setFormattedThrowable(arguments, lastThrowable));
logRepository.addLogMessage(LogLevel.TRACE, getCausesMessage(msg), addCauses(arguments, lastThrowable), lastThrowable);
}
}
}
@Override
public void trace(String msg) {
if (!isTraceEnabled()) {
return;
}
msg = "{} " + msg;
final Object[] os = {component};
logger.trace(msg, os);
logRepository.addLogMessage(LogLevel.TRACE, msg, os);
public void trace(final String msg) {
trace(msg, NULL_THROWABLE);
}
@Override
public void trace(String msg, Object[] os, Throwable t) {
if (!isTraceEnabled()) {
return;
public void trace(final String msg, final Object[] os, final Throwable t) {
if (isTraceEnabled()) {
final String componentMessage = getComponentMessage(msg);
final Object[] arguments = insertComponent(os);
if (t == null) {
logger.trace(componentMessage, arguments);
logRepository.addLogMessage(LogLevel.TRACE, componentMessage, arguments);
} else {
logger.trace(componentMessage, arguments, t);
logRepository.addLogMessage(LogLevel.TRACE, getCausesMessage(msg), addCauses(arguments, t), t);
}
}
os = addProcessorAndThrowable(os, t);
msg = "{} " + msg + ": {}";
logger.trace(msg, os);
logRepository.addLogMessage(LogLevel.TRACE, msg, os, t);
}
@Override
public void trace(LogMessage logMessage) {
public void trace(final LogMessage logMessage) {
if (isTraceEnabled()) {
log(LogLevel.TRACE, logMessage);
logRepository.addLogMessage(logMessage);
@ -204,58 +198,57 @@ public class SimpleProcessLogger implements ComponentLog {
}
@Override
public void info(String msg, Throwable t) {
if (!isInfoEnabled()) {
return;
}
public void info(final String msg, final Throwable t) {
if (isInfoEnabled()) {
final String componentMessage = getComponentMessage(msg);
final Object[] repositoryArguments = getRepositoryArguments(t);
msg = "{} " + msg;
final Object[] os = {component, getCauses(t)};
logger.info(msg, os);
if (logger.isDebugEnabled()) {
logger.info("", t);
if (t == null) {
logger.info(componentMessage, component);
logRepository.addLogMessage(LogLevel.INFO, componentMessage, repositoryArguments);
} else {
logger.info(componentMessage, component, t);
logRepository.addLogMessage(LogLevel.INFO, getCausesMessage(msg), repositoryArguments, t);
}
}
logRepository.addLogMessage(LogLevel.INFO, msg, os, t);
}
@Override
public void info(String msg, Object[] os) {
if (!isInfoEnabled()) {
return;
public void info(final String msg, final Object[] os) {
if (isInfoEnabled()) {
final String componentMessage = getComponentMessage(msg);
final Object[] arguments = insertComponent(os);
final Throwable lastThrowable = findLastThrowable(os);
if (lastThrowable == null) {
logger.info(componentMessage, arguments);
logRepository.addLogMessage(LogLevel.INFO, componentMessage, arguments);
} else {
logger.info(componentMessage, setFormattedThrowable(arguments, lastThrowable));
logRepository.addLogMessage(LogLevel.INFO, getCausesMessage(msg), addCauses(arguments, lastThrowable), lastThrowable);
}
}
msg = "{} " + msg;
os = addProcessor(os);
logger.info(msg, os);
logRepository.addLogMessage(LogLevel.INFO, msg, os);
}
@Override
public void info(String msg) {
if (!isInfoEnabled()) {
return;
}
msg = "{} " + msg;
final Object[] os = {component};
logger.info(msg, os);
logRepository.addLogMessage(LogLevel.INFO, msg, os);
public void info(final String msg) {
info(msg, NULL_THROWABLE);
}
@Override
public void info(String msg, Object[] os, Throwable t) {
if (!isInfoEnabled()) {
return;
public void info(final String msg, final Object[] os, final Throwable t) {
if (isInfoEnabled()) {
final String componentMessage = getComponentMessage(msg);
final Object[] arguments = insertComponent(os);
if (t == null) {
logger.info(componentMessage, arguments);
logRepository.addLogMessage(LogLevel.INFO, componentMessage, arguments);
} else {
logger.info(componentMessage, arguments, t);
logRepository.addLogMessage(LogLevel.INFO, getCausesMessage(msg), addCauses(arguments, t), t);
}
}
os = addProcessorAndThrowable(os, t);
msg = "{} " + msg + ": {}";
logger.info(msg, os);
logRepository.addLogMessage(LogLevel.INFO, msg, os, t);
}
@Override
@ -272,138 +265,123 @@ public class SimpleProcessLogger implements ComponentLog {
}
@Override
public void error(String msg, Throwable t) {
if (!isErrorEnabled()) {
return;
}
public void error(final String msg) {
error(msg, NULL_THROWABLE);
}
if (t == null) {
msg = "{} " + msg;
final Object[] os = new Object[]{component};
logger.error(msg, os);
logRepository.addLogMessage(LogLevel.ERROR, msg, os);
} else {
msg = "{} " + msg + ": {}";
final Object[] os = new Object[]{component, getCauses(t), t};
logger.error(msg, os);
logRepository.addLogMessage(LogLevel.ERROR, msg, os, t);
@Override
public void error(final String msg, final Throwable t) {
if (isErrorEnabled()) {
final String componentMessage = getComponentMessage(msg);
final Object[] repositoryArguments = getRepositoryArguments(t);
if (t == null) {
logger.error(componentMessage, component);
logRepository.addLogMessage(LogLevel.ERROR, componentMessage, repositoryArguments);
} else {
logger.error(componentMessage, component, t);
logRepository.addLogMessage(LogLevel.ERROR, getCausesMessage(msg), repositoryArguments, t);
}
}
}
@Override
public void error(String msg, Object[] os) {
if (!isErrorEnabled()) {
return;
}
public void error(final String msg, final Object[] os) {
if (isErrorEnabled()) {
final String componentMessage = getComponentMessage(msg);
final Object[] arguments = insertComponent(os);
if (lastArgIsException(os)) {
error(msg, os, (Throwable) os[os.length - 1]);
} else {
os = addProcessor(os);
msg = "{} " + msg;
logger.error(msg, os);
logRepository.addLogMessage(LogLevel.ERROR, msg, os);
final Throwable lastThrowable = findLastThrowable(os);
if (lastThrowable == null) {
logger.error(componentMessage, arguments);
logRepository.addLogMessage(LogLevel.ERROR, componentMessage, arguments);
} else {
logger.error(componentMessage, setFormattedThrowable(arguments, lastThrowable));
logRepository.addLogMessage(LogLevel.ERROR, getCausesMessage(msg), addCauses(arguments, lastThrowable), lastThrowable);
}
}
}
@Override
public void error(String msg) {
this.error(msg, (Throwable) null);
}
public void error(final String msg, final Object[] os, final Throwable t) {
if (isErrorEnabled()) {
final String componentMessage = getComponentMessage(msg);
final Object[] arguments = insertComponent(os);
@Override
public void error(String msg, Object[] os, Throwable t) {
if (!isErrorEnabled()) {
return;
if (t == null) {
logger.error(componentMessage, arguments);
logRepository.addLogMessage(LogLevel.ERROR, componentMessage, arguments);
} else {
logger.error(componentMessage, arguments, t);
logRepository.addLogMessage(LogLevel.ERROR, getCausesMessage(msg), addCauses(arguments, t), t);
}
}
os = addProcessorAndThrowable(os, t);
msg = "{} " + msg + ": {}";
logger.error(msg, os);
logRepository.addLogMessage(LogLevel.ERROR, msg, os, t);
}
@Override
public void error(LogMessage logMessage) {
public void error(final LogMessage logMessage) {
if (isErrorEnabled()) {
log(LogLevel.ERROR, logMessage);
logRepository.addLogMessage(logMessage);
}
}
private Object[] addProcessorAndThrowable(final Object[] os, final Throwable t) {
final Object[] modifiedArgs;
if (t == null) {
modifiedArgs = new Object[os.length + 2];
modifiedArgs[0] = component.toString();
System.arraycopy(os, 0, modifiedArgs, 1, os.length);
modifiedArgs[modifiedArgs.length - 1] = StringUtils.EMPTY;
} else {
modifiedArgs = new Object[os.length + 3];
modifiedArgs[0] = component.toString();
System.arraycopy(os, 0, modifiedArgs, 1, os.length);
modifiedArgs[modifiedArgs.length - 2] = getCauses(t);
modifiedArgs[modifiedArgs.length - 1] = t;
}
@Override
public void debug(final String msg, final Throwable t) {
if (isDebugEnabled()) {
final String componentMessage = getComponentMessage(msg);
final Object[] repositoryArguments = getRepositoryArguments(t);
return modifiedArgs;
if (t == null) {
logger.debug(componentMessage, component);
logRepository.addLogMessage(LogLevel.DEBUG, componentMessage, repositoryArguments);
} else {
logger.debug(componentMessage, component, t);
logRepository.addLogMessage(LogLevel.DEBUG, getCausesMessage(msg), repositoryArguments, t);
}
}
}
@Override
public void debug(String msg, Throwable t) {
if (!isDebugEnabled()) {
return;
public void debug(final String msg, final Object[] os) {
if (isDebugEnabled()) {
final String componentMessage = getComponentMessage(msg);
final Object[] arguments = insertComponent(os);
final Throwable lastThrowable = findLastThrowable(os);
if (lastThrowable == null) {
logger.debug(componentMessage, arguments);
logRepository.addLogMessage(LogLevel.DEBUG, componentMessage, arguments);
} else {
logger.debug(componentMessage, setFormattedThrowable(arguments, lastThrowable));
logRepository.addLogMessage(LogLevel.DEBUG, getCausesMessage(msg), addCauses(arguments, lastThrowable), lastThrowable);
}
}
msg = "{} " + msg;
final Object[] os = {component};
logger.debug(msg, os, t);
logRepository.addLogMessage(LogLevel.DEBUG, msg, os, t);
}
@Override
public void debug(String msg, Object[] os) {
if (!isDebugEnabled()) {
return;
public void debug(final String msg, final Object[] os, final Throwable t) {
if (isDebugEnabled()) {
final String componentMessage = getComponentMessage(msg);
final Object[] arguments = insertComponent(os);
if (t == null) {
logger.debug(componentMessage, arguments);
logRepository.addLogMessage(LogLevel.DEBUG, componentMessage, arguments);
} else {
logger.debug(componentMessage, arguments, t);
logRepository.addLogMessage(LogLevel.DEBUG, getCausesMessage(msg), addCauses(arguments, t), t);
}
}
os = addProcessor(os);
msg = "{} " + msg;
logger.debug(msg, os);
logRepository.addLogMessage(LogLevel.DEBUG, msg, os);
}
@Override
public void debug(String msg, Object[] os, Throwable t) {
if (!isDebugEnabled()) {
return;
}
os = addProcessorAndThrowable(os, t);
msg = "{} " + msg + ": {}";
logger.debug(msg, os);
logRepository.addLogMessage(LogLevel.DEBUG, msg, os, t);
public void debug(final String msg) {
debug(msg, NULL_THROWABLE);
}
@Override
public void debug(String msg) {
if (!isDebugEnabled()) {
return;
}
msg = "{} " + msg;
final Object[] os = {component};
logger.debug(msg, os);
logRepository.addLogMessage(LogLevel.DEBUG, msg, os);
}
@Override
public void debug(LogMessage logMessage) {
public void debug(final LogMessage logMessage) {
if (isDebugEnabled()) {
log(LogLevel.DEBUG, logMessage);
logRepository.addLogMessage(logMessage);
@ -411,7 +389,7 @@ public class SimpleProcessLogger implements ComponentLog {
}
@Override
public void log(LogLevel level, String msg, Throwable t) {
public void log(final LogLevel level, final String msg, final Throwable t) {
switch (level) {
case DEBUG:
debug(msg, t);
@ -433,7 +411,7 @@ public class SimpleProcessLogger implements ComponentLog {
}
@Override
public void log(LogLevel level, String msg, Object[] os) {
public void log(final LogLevel level, final String msg, final Object[] os) {
switch (level) {
case DEBUG:
debug(msg, os);
@ -455,7 +433,7 @@ public class SimpleProcessLogger implements ComponentLog {
}
@Override
public void log(LogLevel level, String msg) {
public void log(final LogLevel level, final String msg) {
switch (level) {
case DEBUG:
debug(msg);
@ -477,7 +455,7 @@ public class SimpleProcessLogger implements ComponentLog {
}
@Override
public void log(LogLevel level, String msg, Object[] os, Throwable t) {
public void log(final LogLevel level, final String msg, final Object[] os, final Throwable t) {
switch (level) {
case DEBUG:
debug(msg, os, t);
@ -499,7 +477,7 @@ public class SimpleProcessLogger implements ComponentLog {
}
@Override
public void log(LogMessage message) {
public void log(final LogMessage message) {
switch (message.getLogLevel()) {
case DEBUG:
debug(message);
@ -520,6 +498,29 @@ public class SimpleProcessLogger implements ComponentLog {
}
}
/**
* Get arguments for Log Repository including a summary of Throwable causes when Throwable is found
*
* @param throwable Throwable instance or null
* @return Arguments containing the component or the component and summary of Throwable causes
*/
private Object[] getRepositoryArguments(final Throwable throwable) {
return throwable == null ? new Object[]{component} : getComponentAndCauses(throwable);
}
private String getCausesMessage(final String message) {
return String.format("{} %s: {}", message);
}
private String getComponentMessage(final String message) {
return String.format("{} %s", message);
}
private Object[] getComponentAndCauses(final Throwable throwable) {
final String causes = getCauses(throwable);
return new Object[]{component, causes};
}
private String getCauses(final Throwable throwable) {
final List<String> causes = new ArrayList<>();
for (Throwable cause = throwable; cause != null; cause = cause.getCause()) {
@ -527,4 +528,28 @@ public class SimpleProcessLogger implements ComponentLog {
}
return String.join(CAUSED_BY, causes);
}
private Object[] insertComponent(final Object[] originalArgs) {
return ArrayUtils.insert(0, originalArgs, component);
}
private Object[] addCauses(final Object[] arguments, final Throwable throwable) {
final String causes = getCauses(throwable);
return ArrayUtils.add(arguments, causes);
}
private Object[] setFormattedThrowable(final Object[] arguments, final Throwable throwable) {
final int lastIndex = arguments.length - 1;
final Object[] argumentsThrowableRemoved = ArrayUtils.remove(arguments, lastIndex);
return ArrayUtils.addAll(argumentsThrowableRemoved, throwable.toString(), throwable);
}
private Throwable findLastThrowable(final Object[] arguments) {
final Object lastArgument = (arguments == null || arguments.length == 0) ? null : arguments[arguments.length - 1];
Throwable lastThrowable = null;
if (lastArgument instanceof Throwable) {
lastThrowable = (Throwable) lastArgument;
}
return lastThrowable;
}
}

View File

@ -16,22 +16,22 @@
*/
package org.apache.nifi.processor;
import org.apache.commons.lang3.reflect.FieldUtils;
import org.apache.nifi.components.ConfigurableComponent;
import org.apache.nifi.logging.LogLevel;
import org.apache.nifi.reporting.ReportingTask;
import org.junit.Before;
import org.junit.Test;
import org.apache.nifi.logging.LogRepository;
import org.junit.jupiter.api.BeforeEach;
import org.junit.jupiter.api.Test;
import org.junit.jupiter.api.extension.ExtendWith;
import org.mockito.Mock;
import org.mockito.junit.jupiter.MockitoExtension;
import org.slf4j.Logger;
import java.lang.reflect.Field;
import static org.junit.Assert.fail;
import static org.mockito.ArgumentMatchers.anyString;
import static org.mockito.ArgumentMatchers.eq;
import static org.mockito.Mockito.mock;
import static org.mockito.Mockito.times;
import static org.mockito.Mockito.verify;
import static org.mockito.Mockito.when;
@ExtendWith(MockitoExtension.class)
public class TestSimpleProcessLogger {
private static final String FIRST_MESSAGE = "FIRST";
@ -44,71 +44,210 @@ public class TestSimpleProcessLogger {
String.format("- Caused by: %s: %s", SecurityException.class.getName(), THIRD_MESSAGE)
);
private final Exception e = new IllegalArgumentException(FIRST_MESSAGE, new RuntimeException(SECOND_MESSAGE, new SecurityException(THIRD_MESSAGE)));
private static final Exception EXCEPTION = new IllegalArgumentException(FIRST_MESSAGE, new RuntimeException(SECOND_MESSAGE, new SecurityException(THIRD_MESSAGE)));
private ReportingTask task;
private static final String EXCEPTION_STRING = EXCEPTION.toString();
private static final Throwable NULL_THROWABLE = null;
private static final String FIRST = "FIRST";
private static final int SECOND = 2;
private static final Object[] VALUE_ARGUMENTS = new Object[]{FIRST, SECOND};
private static final Object[] VALUE_EXCEPTION_ARGUMENTS = new Object[]{FIRST, SECOND, EXCEPTION};
private static final String LOG_MESSAGE = "Processed";
private static final String LOG_MESSAGE_WITH_COMPONENT = String.format("{} %s", LOG_MESSAGE);
private static final String LOG_MESSAGE_WITH_COMPONENT_AND_CAUSES = String.format("{} %s: {}", LOG_MESSAGE);
private static final String LOG_ARGUMENTS_MESSAGE = "Processed {} {}";
private static final String LOG_ARGUMENTS_MESSAGE_WITH_COMPONENT = String.format("{} %s", LOG_ARGUMENTS_MESSAGE);
private static final String LOG_ARGUMENTS_MESSAGE_WITH_COMPONENT_AND_CAUSES = String.format("{} %s: {}", LOG_ARGUMENTS_MESSAGE);
@Mock
private ConfigurableComponent component;
@Mock
private LogRepository logRepository;
@Mock
private Logger logger;
private Object[] componentArguments;
private Object[] componentValueArguments;
private Object[] componentValueExceptionStringCausesArguments;
private Object[] componentCausesArguments;
private SimpleProcessLogger componentLog;
private Logger logger;
@BeforeEach
public void setLogger() throws IllegalAccessException {
componentLog = new SimpleProcessLogger(component, logRepository);
FieldUtils.writeDeclaredField(componentLog, "logger", logger, true);
@Before
public void before() {
task = mock(ReportingTask.class);
when(task.getIdentifier()).thenReturn("foo");
when(task.toString()).thenReturn("MyTask");
componentLog = new SimpleProcessLogger(task.getIdentifier(), task);
try {
Field loggerField = componentLog.getClass().getDeclaredField("logger");
loggerField.setAccessible(true);
logger = mock(Logger.class);
componentArguments = new Object[]{component};
componentValueArguments = new Object[]{component, FIRST, SECOND};
componentValueExceptionStringCausesArguments = new Object[]{component, FIRST, SECOND, EXCEPTION, EXPECTED_CAUSES};
componentCausesArguments = new Object[]{component, EXPECTED_CAUSES};
when(logger.isDebugEnabled()).thenReturn(true);
when(logger.isInfoEnabled()).thenReturn(true);
when(logger.isWarnEnabled()).thenReturn(true);
when(logger.isErrorEnabled()).thenReturn(true);
when(logger.isTraceEnabled()).thenReturn(true);
when(logger.isTraceEnabled()).thenReturn(true);
when(logger.isDebugEnabled()).thenReturn(true);
when(logger.isInfoEnabled()).thenReturn(true);
when(logger.isWarnEnabled()).thenReturn(true);
when(logger.isErrorEnabled()).thenReturn(true);
}
loggerField.set(componentLog, logger);
} catch (Exception e) {
e.printStackTrace();
fail(e.getMessage());
@Test
public void testLogLevelMessage() {
for (final LogLevel logLevel : LogLevel.values()) {
componentLog.log(logLevel, LOG_MESSAGE);
switch (logLevel) {
case TRACE:
verify(logger).trace(eq(LOG_MESSAGE_WITH_COMPONENT), eq(component));
break;
case DEBUG:
verify(logger).debug(eq(LOG_MESSAGE_WITH_COMPONENT), eq(component));
break;
case INFO:
verify(logger).info(eq(LOG_MESSAGE_WITH_COMPONENT), eq(component));
break;
case WARN:
verify(logger).warn(eq(LOG_MESSAGE_WITH_COMPONENT), eq(component));
break;
case ERROR:
verify(logger).error(eq(LOG_MESSAGE_WITH_COMPONENT), eq(component));
break;
default:
continue;
}
verify(logRepository).addLogMessage(eq(logLevel), eq(LOG_MESSAGE_WITH_COMPONENT), eq(componentArguments));
}
}
@Test
public void validateDelegateLoggerReceivesThrowableToStringOnError() {
componentLog.error("Hello {}", e);
verify(logger, times(1)).error(anyString(), eq(task), eq(EXPECTED_CAUSES), eq(e));
public void testLogLevelMessageArguments() {
for (final LogLevel logLevel : LogLevel.values()) {
componentLog.log(logLevel, LOG_ARGUMENTS_MESSAGE, VALUE_ARGUMENTS);
switch (logLevel) {
case TRACE:
verify(logger).trace(eq(LOG_ARGUMENTS_MESSAGE_WITH_COMPONENT), eq(component), eq(FIRST), eq(SECOND));
break;
case DEBUG:
verify(logger).debug(eq(LOG_ARGUMENTS_MESSAGE_WITH_COMPONENT), eq(component), eq(FIRST), eq(SECOND));
break;
case INFO:
verify(logger).info(eq(LOG_ARGUMENTS_MESSAGE_WITH_COMPONENT), eq(component), eq(FIRST), eq(SECOND));
break;
case WARN:
verify(logger).warn(eq(LOG_ARGUMENTS_MESSAGE_WITH_COMPONENT), eq(component), eq(FIRST), eq(SECOND));
break;
case ERROR:
verify(logger).error(eq(LOG_ARGUMENTS_MESSAGE_WITH_COMPONENT), eq(component), eq(FIRST), eq(SECOND));
break;
default:
continue;
}
verify(logRepository).addLogMessage(eq(logLevel), eq(LOG_ARGUMENTS_MESSAGE_WITH_COMPONENT), eq(componentValueArguments));
}
}
@Test
public void validateDelegateLoggerReceivesThrowableToStringOnInfo() {
componentLog.info("Hello {}", e);
verify(logger, times(1)).info(anyString(), eq(e));
public void testLogLevelMessageThrowable() {
for (final LogLevel logLevel : LogLevel.values()) {
componentLog.log(logLevel, LOG_MESSAGE, EXCEPTION);
switch (logLevel) {
case TRACE:
verify(logger).trace(eq(LOG_MESSAGE_WITH_COMPONENT), eq(component), eq(EXCEPTION));
break;
case DEBUG:
verify(logger).debug(eq(LOG_MESSAGE_WITH_COMPONENT), eq(component), eq(EXCEPTION));
break;
case INFO:
verify(logger).info(eq(LOG_MESSAGE_WITH_COMPONENT), eq(component), eq(EXCEPTION));
break;
case WARN:
verify(logger).warn(eq(LOG_MESSAGE_WITH_COMPONENT), eq(component), eq(EXCEPTION));
break;
case ERROR:
verify(logger).error(eq(LOG_MESSAGE_WITH_COMPONENT), eq(component), eq(EXCEPTION));
break;
default:
continue;
}
verify(logRepository).addLogMessage(eq(logLevel), eq(LOG_MESSAGE_WITH_COMPONENT_AND_CAUSES), eq(componentCausesArguments), eq(EXCEPTION));
}
}
@Test
public void validateDelegateLoggerReceivesThrowableToStringOnTrace() {
componentLog.trace("Hello {}", e);
verify(logger, times(1)).trace(anyString(), eq(task), eq(EXPECTED_CAUSES), eq(e));
public void testLogLevelMessageArgumentsThrowable() {
for (final LogLevel logLevel : LogLevel.values()) {
componentLog.log(logLevel, LOG_ARGUMENTS_MESSAGE, VALUE_EXCEPTION_ARGUMENTS);
switch (logLevel) {
case TRACE:
verify(logger).trace(eq(LOG_ARGUMENTS_MESSAGE_WITH_COMPONENT), eq(component), eq(FIRST), eq(SECOND), eq(EXCEPTION_STRING), eq(EXCEPTION));
break;
case DEBUG:
verify(logger).debug(eq(LOG_ARGUMENTS_MESSAGE_WITH_COMPONENT), eq(component), eq(FIRST), eq(SECOND), eq(EXCEPTION_STRING), eq(EXCEPTION));
break;
case INFO:
verify(logger).info(eq(LOG_ARGUMENTS_MESSAGE_WITH_COMPONENT), eq(component), eq(FIRST), eq(SECOND), eq(EXCEPTION_STRING), eq(EXCEPTION));
break;
case WARN:
verify(logger).warn(eq(LOG_ARGUMENTS_MESSAGE_WITH_COMPONENT), eq(component), eq(FIRST), eq(SECOND), eq(EXCEPTION_STRING), eq(EXCEPTION));
break;
case ERROR:
verify(logger).error(eq(LOG_ARGUMENTS_MESSAGE_WITH_COMPONENT), eq(component), eq(FIRST), eq(SECOND), eq(EXCEPTION_STRING), eq(EXCEPTION));
break;
default:
continue;
}
verify(logRepository).addLogMessage(eq(logLevel), eq(LOG_ARGUMENTS_MESSAGE_WITH_COMPONENT_AND_CAUSES), eq(componentValueExceptionStringCausesArguments), eq(EXCEPTION));
}
}
@Test
public void validateDelegateLoggerReceivesThrowableToStringOnWarn() {
componentLog.warn("Hello {}", e);
verify(logger, times(1)).warn(anyString(), eq(task), eq(EXPECTED_CAUSES), eq(e));
}
public void testLogLevelMessageArgumentsThrowableNull() {
for (final LogLevel logLevel : LogLevel.values()) {
componentLog.log(logLevel, LOG_ARGUMENTS_MESSAGE, VALUE_ARGUMENTS, NULL_THROWABLE);
@Test
public void validateDelegateLoggerReceivesThrowableToStringOnLogWithLevel() {
componentLog.log(LogLevel.WARN, "Hello {}", e);
verify(logger, times(1)).warn(anyString(), eq(task), eq(EXPECTED_CAUSES), eq(e));
componentLog.log(LogLevel.ERROR, "Hello {}", e);
verify(logger, times(1)).error(anyString(), eq(task), eq(EXPECTED_CAUSES), eq(e));
componentLog.log(LogLevel.INFO, "Hello {}", e);
verify(logger, times(1)).info(anyString(), eq(e));
componentLog.log(LogLevel.TRACE, "Hello {}", e);
verify(logger, times(1)).trace(anyString(), eq(task), eq(EXPECTED_CAUSES), eq(e));
switch (logLevel) {
case TRACE:
verify(logger).trace(eq(LOG_ARGUMENTS_MESSAGE_WITH_COMPONENT), eq(component), eq(FIRST), eq(SECOND));
break;
case DEBUG:
verify(logger).debug(eq(LOG_ARGUMENTS_MESSAGE_WITH_COMPONENT), eq(component), eq(FIRST), eq(SECOND));
break;
case INFO:
verify(logger).info(eq(LOG_ARGUMENTS_MESSAGE_WITH_COMPONENT), eq(component), eq(FIRST), eq(SECOND));
break;
case WARN:
verify(logger).warn(eq(LOG_ARGUMENTS_MESSAGE_WITH_COMPONENT), eq(component), eq(FIRST), eq(SECOND));
break;
case ERROR:
verify(logger).error(eq(LOG_ARGUMENTS_MESSAGE_WITH_COMPONENT), eq(component), eq(FIRST), eq(SECOND));
break;
default:
continue;
}
verify(logRepository).addLogMessage(eq(logLevel), eq(LOG_ARGUMENTS_MESSAGE_WITH_COMPONENT), eq(componentValueArguments));
}
}
}

View File

@ -242,19 +242,16 @@ public class ConnectableTask {
shouldRun = repositoryContext.isRelationshipAvailabilitySatisfied(requiredNumberOfAvailableRelationships);
}
}
} catch (final TerminatedTaskException tte) {
final ComponentLog procLog = new SimpleProcessLogger(connectable.getIdentifier(), connectable.getRunnableComponent());
procLog.info("Failed to process session due to task being terminated", new Object[] {tte});
} catch (final ProcessException pe) {
final ComponentLog procLog = new SimpleProcessLogger(connectable.getIdentifier(), connectable.getRunnableComponent());
procLog.error("Failed to process session due to {}", new Object[] {pe});
} catch (final Throwable t) {
// Use ComponentLog to log the event so that a bulletin will be created for this processor
final ComponentLog procLog = new SimpleProcessLogger(connectable.getIdentifier(), connectable.getRunnableComponent());
procLog.error("Failed to process session due to {}; Processor Administratively Yielded for {}",
new Object[] {t, schedulingAgent.getAdministrativeYieldDuration()}, t);
logger.warn("Administratively Yielding {} due to uncaught Exception: {}", connectable.getRunnableComponent(), t.toString(), t);
} catch (final TerminatedTaskException e) {
final ComponentLog componentLog = getComponentLog();
componentLog.info("Processing terminated", e);
} catch (final ProcessException e) {
final ComponentLog componentLog = getComponentLog();
componentLog.error("Processing failed", e);
} catch (final Throwable e) {
final ComponentLog componentLog = getComponentLog();
componentLog.error("Processing halted: yielding [{}]", schedulingAgent.getAdministrativeYieldDuration(), e);
logger.warn("Processing halted: uncaught exception in Component [{}]", connectable.getRunnableComponent(), e);
connectable.yield(schedulingAgent.getAdministrativeYieldDuration(TimeUnit.NANOSECONDS), TimeUnit.NANOSECONDS);
}
} finally {
@ -291,4 +288,7 @@ public class ConnectableTask {
return InvocationResult.DO_NOT_YIELD;
}
private ComponentLog getComponentLog() {
return new SimpleProcessLogger(connectable.getIdentifier(), connectable.getRunnableComponent());
}
}