protected void assertCommandExecutionEvents(
HystrixInvokableInfo<?> command, HystrixEventType... expectedEventTypes) {
boolean emitExpected = false;
int expectedEmitCount = 0;
boolean fallbackEmitExpected = false;
int expectedFallbackEmitCount = 0;
List<HystrixEventType> condensedEmitExpectedEventTypes = new ArrayList<HystrixEventType>();
for (HystrixEventType expectedEventType : expectedEventTypes) {
if (expectedEventType.equals(HystrixEventType.EMIT)) {
if (!emitExpected) {
// first EMIT encountered, add it to condensedEmitExpectedEventTypes
condensedEmitExpectedEventTypes.add(HystrixEventType.EMIT);
}
emitExpected = true;
expectedEmitCount++;
} else if (expectedEventType.equals(HystrixEventType.FALLBACK_EMIT)) {
if (!fallbackEmitExpected) {
// first FALLBACK_EMIT encountered, add it to condensedEmitExpectedEventTypes
condensedEmitExpectedEventTypes.add(HystrixEventType.FALLBACK_EMIT);
}
fallbackEmitExpected = true;
expectedFallbackEmitCount++;
} else {
condensedEmitExpectedEventTypes.add(expectedEventType);
}
}
List<HystrixEventType> actualEventTypes = command.getExecutionEvents();
assertEquals(expectedEmitCount, command.getNumberEmissions());
assertEquals(expectedFallbackEmitCount, command.getNumberFallbackEmissions());
assertEquals(condensedEmitExpectedEventTypes, actualEventTypes);
}
private <T> void logHC(HystrixInvokable<T> command, T response) {
if (command instanceof HystrixInvokableInfo) {
HystrixInvokableInfo<T> commandInfo = (HystrixInvokableInfo<T>) command;
HystrixCommandMetrics metrics = commandInfo.getMetrics();
System.out.println(
"cb/error-count/%/total: "
+ commandInfo.isCircuitBreakerOpen()
+ " "
+ metrics.getHealthCounts().getErrorCount()
+ " "
+ metrics.getHealthCounts().getErrorPercentage()
+ " "
+ metrics.getHealthCounts().getTotalRequests()
+ " => "
+ response
+ " "
+ commandInfo.getExecutionEvents());
}
}
/**
* Formats the log of executed commands into a string usable for logging purposes.
*
* <p>Examples:
*
* <ul>
* <li>TestCommand[SUCCESS][1ms]
* <li>TestCommand[SUCCESS][1ms], TestCommand[SUCCESS, RESPONSE_FROM_CACHE][1ms]x4
* <li>TestCommand[TIMEOUT][1ms]
* <li>TestCommand[FAILURE][1ms]
* <li>TestCommand[THREAD_POOL_REJECTED][1ms]
* <li>TestCommand[THREAD_POOL_REJECTED, FALLBACK_SUCCESS][1ms]
* <li>TestCommand[EMIT, SUCCESS][1ms]
* <li>TestCommand[EMITx5, SUCCESS][1ms]
* <li>TestCommand[EMITx5, FAILURE, FALLBACK_EMITx6, FALLBACK_FAILURE][100ms]
* <li>TestCommand[FAILURE, FALLBACK_SUCCESS][1ms], TestCommand[FAILURE, FALLBACK_SUCCESS,
* RESPONSE_FROM_CACHE][1ms]x4
* <li>GetData[SUCCESS][1ms], PutData[SUCCESS][1ms], GetValues[SUCCESS][1ms], GetValues[SUCCESS,
* RESPONSE_FROM_CACHE][1ms], TestCommand[FAILURE, FALLBACK_FAILURE][1ms],
* TestCommand[FAILURE, FALLBACK_FAILURE, RESPONSE_FROM_CACHE][1ms]
* </ul>
*
* <p>If a command has a multiplier such as <code>x4</code>, that means this command was executed
* 4 times with the same events. The time in milliseconds is the sum of the 4 executions.
*
* <p>For example, <code>TestCommand[SUCCESS][15ms]x4</code> represents TestCommand being executed
* 4 times and the sum of those 4 executions was 15ms. These 4 each executed the run() method
* since <code>RESPONSE_FROM_CACHE</code> was not present as an event.
*
* <p>If an EMIT or FALLBACK_EMIT has a multiplier such as <code>x5</code>, that means a <code>
* HystrixObservableCommand</code> was used and it emitted that number of <code>OnNext</code>s.
*
* <p>For example, <code>TestCommand[EMITx5, FAILURE, FALLBACK_EMITx6, FALLBACK_FAILURE][100ms]
* </code> represents TestCommand executing observably, emitted 5 <code>OnNext</code>s, then an
* <code>OnError</code>. This command also has an Observable fallback, and it emits 6 <code>OnNext
* </code>s, then an <code>OnCompleted</code>.
*
* @return String request log or "Unknown" if unable to instead of throwing an exception.
*/
public String getExecutedCommandsAsString() {
try {
LinkedHashMap<String, Integer> aggregatedCommandsExecuted =
new LinkedHashMap<String, Integer>();
Map<String, Integer> aggregatedCommandExecutionTime = new HashMap<String, Integer>();
StringBuilder builder = new StringBuilder();
int estimatedLength = 0;
for (HystrixInvokableInfo<?> command : allExecutedCommands) {
builder.setLength(0);
builder.append(command.getCommandKey().name());
List<HystrixEventType> events =
new ArrayList<HystrixEventType>(command.getExecutionEvents());
if (events.size() > 0) {
Collections.sort(events);
// replicate functionality of Arrays.toString(events.toArray()) to append directly to
// existing StringBuilder
builder.append("[");
for (HystrixEventType event : events) {
switch (event) {
case EMIT:
int numEmissions = command.getNumberEmissions();
if (numEmissions > 1) {
builder.append(event).append("x").append(numEmissions).append(", ");
} else {
builder.append(event).append(", ");
}
break;
case FALLBACK_EMIT:
int numFallbackEmissions = command.getNumberFallbackEmissions();
if (numFallbackEmissions > 1) {
builder.append(event).append("x").append(numFallbackEmissions).append(", ");
} else {
builder.append(event).append(", ");
}
break;
default:
builder.append(event).append(", ");
}
}
builder.setCharAt(builder.length() - 2, ']');
builder.setLength(builder.length() - 1);
} else {
builder.append("[Executed]");
}
String display = builder.toString();
estimatedLength +=
display.length()
+ 12; // add 12 chars to display length for appending totalExecutionTime and count
// below
Integer counter = aggregatedCommandsExecuted.get(display);
if (counter != null) {
aggregatedCommandsExecuted.put(display, counter + 1);
} else {
// add it
aggregatedCommandsExecuted.put(display, 1);
}
int executionTime = command.getExecutionTimeInMilliseconds();
if (executionTime < 0) {
// do this so we don't create negative values or subtract values
executionTime = 0;
}
counter = aggregatedCommandExecutionTime.get(display);
if (counter != null && executionTime > 0) {
// add to the existing executionTime (sum of executionTimes for duplicate command
// displayNames)
aggregatedCommandExecutionTime.put(
display, aggregatedCommandExecutionTime.get(display) + executionTime);
} else {
// add it
aggregatedCommandExecutionTime.put(display, executionTime);
}
}
builder.setLength(0);
builder.ensureCapacity(estimatedLength);
for (String displayString : aggregatedCommandsExecuted.keySet()) {
if (builder.length() > 0) {
builder.append(", ");
}
builder.append(displayString);
int totalExecutionTime = aggregatedCommandExecutionTime.get(displayString);
builder.append("[").append(totalExecutionTime).append("ms]");
int count = aggregatedCommandsExecuted.get(displayString);
if (count > 1) {
builder.append("x").append(count);
}
}
return builder.toString();
} catch (Exception e) {
logger.error("Failed to create HystrixRequestLog response header string.", e);
// don't let this cause the entire app to fail so just return "Unknown"
return "Unknown";
}
}
