use of com.unboundid.ldap.sdk.unboundidds.logs.v2.text.TextFormattedAccessLogReader in project ldapsdk by pingidentity.
the class SummarizeAccessLog method doToolProcessing.
/**
* Performs the core set of processing for this tool.
*
* @return A result code that indicates whether the processing completed
* successfully.
*/
@Override()
@NotNull()
public ResultCode doToolProcessing() {
int displayCount = reportCount.getValue();
if (displayCount <= 0) {
displayCount = Integer.MAX_VALUE;
}
String encryptionPassphrase = null;
if (encryptionPassphraseFile.isPresent()) {
try {
encryptionPassphrase = ToolUtils.readEncryptionPassphraseFromFile(encryptionPassphraseFile.getValue());
} catch (final LDAPException e) {
Debug.debugException(e);
err(e.getMessage());
return e.getResultCode();
}
}
long logLines = 0L;
for (final String path : argumentParser.getTrailingArguments()) {
final File f = new File(path);
out("Examining access log ", f.getAbsolutePath());
AccessLogReader reader = null;
InputStream inputStream = null;
try {
inputStream = new FileInputStream(f);
final ObjectPair<InputStream, String> p = ToolUtils.getPossiblyPassphraseEncryptedInputStream(inputStream, encryptionPassphrase, (!encryptionPassphraseFile.isPresent()), "Log file '" + path + "' is encrypted. Please enter the " + "encryption passphrase:", "ERROR: The provided passphrase was incorrect.", getOut(), getErr());
inputStream = p.getFirst();
if ((p.getSecond() != null) && (encryptionPassphrase == null)) {
encryptionPassphrase = p.getSecond();
}
if (isCompressed.isPresent()) {
inputStream = new GZIPInputStream(inputStream);
} else {
inputStream = ToolUtils.getPossiblyGZIPCompressedInputStream(inputStream);
}
if (json.isPresent()) {
reader = new JSONAccessLogReader(inputStream);
} else {
reader = new TextFormattedAccessLogReader(inputStream);
}
} catch (final Exception e) {
Debug.debugException(e);
err("Unable to open access log file ", f.getAbsolutePath(), ": ", StaticUtils.getExceptionMessage(e));
return ResultCode.LOCAL_ERROR;
} finally {
if ((reader == null) && (inputStream != null)) {
try {
inputStream.close();
} catch (final Exception e) {
Debug.debugException(e);
}
}
}
long startTime = 0L;
long stopTime = 0L;
while (true) {
final AccessLogMessage msg;
try {
msg = reader.readMessage();
} catch (final IOException ioe) {
Debug.debugException(ioe);
err("Error reading from access log file ", f.getAbsolutePath(), ": ", StaticUtils.getExceptionMessage(ioe));
if ((ioe.getCause() != null) && (ioe.getCause() instanceof BadPaddingException)) {
err("This error is likely because the log is encrypted and the " + "server still has the log file open. It is recommended " + "that you only try to examine encrypted logs after they " + "have been rotated. You can use the rotate-log tool to " + "force a rotation at any time. Attempting to proceed with " + "just the data that was successfully read.");
break;
} else {
return ResultCode.LOCAL_ERROR;
}
} catch (final LogException le) {
Debug.debugException(le);
err("Encountered an error while attempting to parse a line in" + "access log file ", f.getAbsolutePath(), ": ", StaticUtils.getExceptionMessage(le));
continue;
}
if (msg == null) {
break;
}
logLines++;
stopTime = msg.getTimestamp().getTime();
if (startTime == 0L) {
startTime = stopTime;
}
switch(msg.getMessageType()) {
case CONNECT:
processConnect((ConnectAccessLogMessage) msg);
break;
case SECURITY_NEGOTIATION:
processSecurityNegotiation((SecurityNegotiationAccessLogMessage) msg);
break;
case DISCONNECT:
processDisconnect((DisconnectAccessLogMessage) msg);
break;
case REQUEST:
switch(((OperationRequestAccessLogMessage) msg).getOperationType()) {
case ABANDON:
processAbandonRequest((AbandonRequestAccessLogMessage) msg);
break;
case EXTENDED:
processExtendedRequest((ExtendedRequestAccessLogMessage) msg);
break;
case SEARCH:
processSearchRequest((SearchRequestAccessLogMessage) msg);
break;
case UNBIND:
processUnbindRequest((UnbindRequestAccessLogMessage) msg);
break;
}
break;
case RESULT:
switch(((OperationRequestAccessLogMessage) msg).getOperationType()) {
case ADD:
processAddResult((AddResultAccessLogMessage) msg);
break;
case BIND:
processBindResult((BindResultAccessLogMessage) msg);
break;
case COMPARE:
processCompareResult((CompareResultAccessLogMessage) msg);
break;
case DELETE:
processDeleteResult((DeleteResultAccessLogMessage) msg);
break;
case EXTENDED:
processExtendedResult((ExtendedResultAccessLogMessage) msg);
break;
case MODIFY:
processModifyResult((ModifyResultAccessLogMessage) msg);
break;
case MODDN:
processModifyDNResult((ModifyDNResultAccessLogMessage) msg);
break;
case SEARCH:
processSearchResult((SearchResultAccessLogMessage) msg);
break;
}
break;
case ASSURANCE_COMPLETE:
case CLIENT_CERTIFICATE:
case ENTRY_REBALANCING_REQUEST:
case ENTRY_REBALANCING_RESULT:
case FORWARD:
case FORWARD_FAILED:
case ENTRY:
case REFERENCE:
default:
}
}
try {
reader.close();
} catch (final Exception e) {
Debug.debugException(e);
}
logDurationMillis += (stopTime - startTime);
}
final int numFiles = argumentParser.getTrailingArguments().size();
out();
out("Examined ", logLines, " lines in ", numFiles, ((numFiles == 1) ? " file" : " files"), " covering a total duration of ", StaticUtils.millisToHumanReadableDuration(logDurationMillis));
if (logLines == 0) {
return ResultCode.SUCCESS;
}
out();
final double logDurationSeconds = logDurationMillis / 1_000.0;
final double connectsPerSecond = numConnects / logDurationSeconds;
final double disconnectsPerSecond = numDisconnects / logDurationSeconds;
out("Total connections established: ", numConnects, " (", decimalFormat.format(connectsPerSecond), "/second)");
out("Total disconnects: ", numDisconnects, " (", decimalFormat.format(disconnectsPerSecond), "/second)");
printCounts(clientAddresses, "Most common client addresses:", "address", "addresses");
printCounts(clientConnectionPolicies, "Most common client connection policies:", "policy", "policies");
printCounts(tlsProtocols, "Most common TLS protocol versions:", "version", "versions");
printCounts(tlsCipherSuites, "Most common TLS cipher suites:", "cipher suite", "cipher suites");
printCounts(disconnectReasons, "Most common disconnect reasons:", "reason", "reasons");
final long totalOps = numAbandons + numAdds + numBinds + numCompares + numDeletes + numExtended + numModifies + numModifyDNs + numSearches + numUnbinds;
if (totalOps > 0) {
final double percentAbandon = 100.0 * numAbandons / totalOps;
final double percentAdd = 100.0 * numAdds / totalOps;
final double percentBind = 100.0 * numBinds / totalOps;
final double percentCompare = 100.0 * numCompares / totalOps;
final double percentDelete = 100.0 * numDeletes / totalOps;
final double percentExtended = 100.0 * numExtended / totalOps;
final double percentModify = 100.0 * numModifies / totalOps;
final double percentModifyDN = 100.0 * numModifyDNs / totalOps;
final double percentSearch = 100.0 * numSearches / totalOps;
final double percentUnbind = 100.0 * numUnbinds / totalOps;
final double abandonsPerSecond = numAbandons / logDurationSeconds;
final double addsPerSecond = numAdds / logDurationSeconds;
final double bindsPerSecond = numBinds / logDurationSeconds;
final double comparesPerSecond = numCompares / logDurationSeconds;
final double deletesPerSecond = numDeletes / logDurationSeconds;
final double extendedPerSecond = numExtended / logDurationSeconds;
final double modifiesPerSecond = numModifies / logDurationSeconds;
final double modifyDNsPerSecond = numModifyDNs / logDurationSeconds;
final double searchesPerSecond = numSearches / logDurationSeconds;
final double unbindsPerSecond = numUnbinds / logDurationSeconds;
out();
out("Total operations examined: ", totalOps);
out("Abandon operations examined: ", numAbandons, " (", decimalFormat.format(percentAbandon), "%, ", decimalFormat.format(abandonsPerSecond), "/second)");
out("Add operations examined: ", numAdds, " (", decimalFormat.format(percentAdd), "%, ", decimalFormat.format(addsPerSecond), "/second)");
out("Bind operations examined: ", numBinds, " (", decimalFormat.format(percentBind), "%, ", decimalFormat.format(bindsPerSecond), "/second)");
out("Compare operations examined: ", numCompares, " (", decimalFormat.format(percentCompare), "%, ", decimalFormat.format(comparesPerSecond), "/second)");
out("Delete operations examined: ", numDeletes, " (", decimalFormat.format(percentDelete), "%, ", decimalFormat.format(deletesPerSecond), "/second)");
out("Extended operations examined: ", numExtended, " (", decimalFormat.format(percentExtended), "%, ", decimalFormat.format(extendedPerSecond), "/second)");
out("Modify operations examined: ", numModifies, " (", decimalFormat.format(percentModify), "%, ", decimalFormat.format(modifiesPerSecond), "/second)");
out("Modify DN operations examined: ", numModifyDNs, " (", decimalFormat.format(percentModifyDN), "%, ", decimalFormat.format(modifyDNsPerSecond), "/second)");
out("Search operations examined: ", numSearches, " (", decimalFormat.format(percentSearch), "%, ", decimalFormat.format(searchesPerSecond), "/second)");
out("Unbind operations examined: ", numUnbinds, " (", decimalFormat.format(percentUnbind), "%, ", decimalFormat.format(unbindsPerSecond), "/second)");
final double totalProcessingDuration = addProcessingDuration + bindProcessingDuration + compareProcessingDuration + deleteProcessingDuration + extendedProcessingDuration + modifyProcessingDuration + modifyDNProcessingDuration + searchProcessingDuration;
out();
out("Average operation processing duration: ", decimalFormat.format(totalProcessingDuration / totalOps), "ms");
if (numAdds > 0) {
out("Average add operation processing duration: ", decimalFormat.format(addProcessingDuration / numAdds), "ms");
}
if (numBinds > 0) {
out("Average bind operation processing duration: ", decimalFormat.format(bindProcessingDuration / numBinds), "ms");
}
if (numCompares > 0) {
out("Average compare operation processing duration: ", decimalFormat.format(compareProcessingDuration / numCompares), "ms");
}
if (numDeletes > 0) {
out("Average delete operation processing duration: ", decimalFormat.format(deleteProcessingDuration / numDeletes), "ms");
}
if (numExtended > 0) {
out("Average extended operation processing duration: ", decimalFormat.format(extendedProcessingDuration / numExtended), "ms");
}
if (numModifies > 0) {
out("Average modify operation processing duration: ", decimalFormat.format(modifyProcessingDuration / numModifies), "ms");
}
if (numModifyDNs > 0) {
out("Average modify DN operation processing duration: ", decimalFormat.format(modifyDNProcessingDuration / numModifyDNs), "ms");
}
if (numSearches > 0) {
out("Average search operation processing duration: ", decimalFormat.format(searchProcessingDuration / numSearches), "ms");
}
printProcessingTimeHistogram("add", numAdds, addProcessingTimes);
printProcessingTimeHistogram("bind", numBinds, bindProcessingTimes);
printProcessingTimeHistogram("compare", numCompares, compareProcessingTimes);
printProcessingTimeHistogram("delete", numDeletes, deleteProcessingTimes);
printProcessingTimeHistogram("extended", numExtended, extendedProcessingTimes);
printProcessingTimeHistogram("modify", numModifies, modifyProcessingTimes);
printProcessingTimeHistogram("modify DN", numModifyDNs, modifyDNProcessingTimes);
printProcessingTimeHistogram("search", numSearches, searchProcessingTimes);
printResultCodeCounts(addResultCodes, "add");
printResultCodeCounts(bindResultCodes, "bind");
printResultCodeCounts(compareResultCodes, "compare");
printResultCodeCounts(deleteResultCodes, "delete");
printResultCodeCounts(extendedResultCodes, "extended");
printResultCodeCounts(modifyResultCodes, "modify");
printResultCodeCounts(modifyDNResultCodes, "modify DN");
printResultCodeCounts(searchResultCodes, "search");
printCounts(successfulBindDNs, "Most common bind DNs used in successful authentication attempts:", "DN", "DNs");
printCounts(failedBindDNs, "Most common bind DNs used in failed authentication attempts:", "DN", "DNs");
printCounts(authenticationTypes, "Most common authentication types:", "authentication type", "authentication types");
long numResultsWithAuthzID = 0L;
for (final AtomicLong l : authzDNs.values()) {
numResultsWithAuthzID += l.get();
}
out();
final double percentWithAuthzID = 100.0 * numResultsWithAuthzID / totalOps;
out("Number of operations with an alternate authorization identity: ", numResultsWithAuthzID, " (", decimalFormat.format(percentWithAuthzID), "%)");
printCounts(authzDNs, "Most common alternate authorization identity DNs:", "DN", "DNs");
if (!extendedOperations.isEmpty()) {
final List<ObjectPair<String, Long>> extOpCounts = new ArrayList<>();
final AtomicLong skippedWithSameCount = new AtomicLong(0L);
final AtomicLong skippedWithLowerCount = new AtomicLong(0L);
getMostCommonElements(extendedOperations, extOpCounts, displayCount, skippedWithSameCount, skippedWithLowerCount);
out();
out("Most common extended operation types:");
long count = -1L;
for (final ObjectPair<String, Long> p : extOpCounts) {
count = p.getSecond();
final double percent = 100.0 * count / numExtended;
final String oid = p.getFirst();
final String name = extendedOperationOIDsToNames.get(oid);
if (name == null) {
out(p.getFirst(), ": ", p.getSecond(), " (", decimalFormat.format(percent), "%)");
} else {
out(p.getFirst(), " (", name, "): ", p.getSecond(), " (", decimalFormat.format(percent), "%)");
}
}
if (skippedWithSameCount.get() > 0L) {
out("{ Skipped " + skippedWithSameCount.get() + " additional extended " + getSingularOrPlural(skippedWithSameCount.get(), "operation", "operations") + " with a count of " + count + " }");
}
if (skippedWithLowerCount.get() > 0L) {
out("{ Skipped " + skippedWithLowerCount.get() + " additional extended " + getSingularOrPlural(skippedWithLowerCount.get(), "operation", "operations") + " with a count that is less than " + count + " }");
}
}
out();
out("Number of unindexed search attempts: ", numUnindexedAttempts);
out("Number of successfully-completed unindexed searches: ", numUnindexedSuccessful);
out("Number of failed unindexed searches: ", numUnindexedFailed);
printCounts(unindexedFilters, "Most common unindexed search filters:", "filter", "filters");
if (!searchScopes.isEmpty()) {
final List<ObjectPair<SearchScope, Long>> scopeCounts = new ArrayList<>();
final AtomicLong skippedWithSameCount = new AtomicLong(0L);
final AtomicLong skippedWithLowerCount = new AtomicLong(0L);
getMostCommonElements(searchScopes, scopeCounts, displayCount, skippedWithSameCount, skippedWithLowerCount);
out();
out("Most common search scopes:");
long count = -1L;
for (final ObjectPair<SearchScope, Long> p : scopeCounts) {
count = p.getSecond();
final double percent = 100.0 * count / numSearches;
out(p.getFirst().getName().toLowerCase(), " (", p.getFirst().intValue(), "): ", p.getSecond(), " (", decimalFormat.format(percent), "%)");
}
if (skippedWithSameCount.get() > 0L) {
out("{ Skipped " + skippedWithSameCount.get() + " additional " + getSingularOrPlural(skippedWithSameCount.get(), "scope", "scopes") + " with a count of " + count + " }");
}
if (skippedWithLowerCount.get() > 0L) {
out("{ Skipped " + skippedWithLowerCount.get() + " additional " + getSingularOrPlural(skippedWithLowerCount.get(), "scope", "scopes") + " with a count that is less than " + count + " }");
}
}
if (!searchEntryCounts.isEmpty()) {
final List<ObjectPair<Long, Long>> entryCounts = new ArrayList<>();
final AtomicLong skippedWithSameCount = new AtomicLong(0L);
final AtomicLong skippedWithLowerCount = new AtomicLong(0L);
getMostCommonElements(searchEntryCounts, entryCounts, displayCount, skippedWithSameCount, skippedWithLowerCount);
out();
out("Most common search entry counts:");
long count = -1L;
for (final ObjectPair<Long, Long> p : entryCounts) {
count = p.getSecond();
final double percent = 100.0 * count / numSearches;
out(p.getFirst(), " matching ", getSingularOrPlural(p.getFirst(), "entry", "entries"), ": ", p.getSecond(), " (", decimalFormat.format(percent), "%)");
}
if (skippedWithSameCount.get() > 0L) {
out("{ Skipped " + skippedWithSameCount.get() + " additional entry " + getSingularOrPlural(skippedWithSameCount.get(), "count", "counts") + " with a count of " + count + " }");
}
if (skippedWithLowerCount.get() > 0L) {
out("{ Skipped " + skippedWithLowerCount.get() + " additional entry " + getSingularOrPlural(skippedWithLowerCount.get(), "count", "counts") + " with a count that is less than " + count + " }");
}
}
printCounts(searchBaseDNs, "Most common base DNs for searches with a non-base scope:", "base DN", "base DNs");
printCounts(filterTypes, "Most common filters for searches with a non-base scope:", "filter", "filters");
if (numSearches > 0L) {
long numSearchesMatchingNoEntries = 0L;
for (final AtomicLong l : noEntryFilters.values()) {
numSearchesMatchingNoEntries += l.get();
}
out();
final double noEntryPercent = 100.0 * numSearchesMatchingNoEntries / numSearches;
out("Number of searches matching no entries: ", numSearchesMatchingNoEntries, " (", decimalFormat.format(noEntryPercent), "%)");
printCounts(noEntryFilters, "Most common filters for searches matching no entries:", "filter", "filters");
long numSearchesMatchingOneEntry = 0L;
for (final AtomicLong l : oneEntryFilters.values()) {
numSearchesMatchingOneEntry += l.get();
}
out();
final double oneEntryPercent = 100.0 * numSearchesMatchingOneEntry / numSearches;
out("Number of searches matching one entry: ", numSearchesMatchingOneEntry, " (", decimalFormat.format(oneEntryPercent), "%)");
printCounts(oneEntryFilters, "Most common filters for searches matching one entry:", "filter", "filters");
long numSearchesMatchingMultipleEntries = 0L;
for (final AtomicLong l : multiEntryFilters.values()) {
numSearchesMatchingMultipleEntries += l.get();
}
out();
final double multiEntryPercent = 100.0 * numSearchesMatchingMultipleEntries / numSearches;
out("Number of searches matching multiple entries: ", numSearchesMatchingMultipleEntries, " (", decimalFormat.format(multiEntryPercent), "%)");
printCounts(multiEntryFilters, "Most common filters for searches matching multiple entries:", "filter", "filters");
}
}
if (!mostExpensiveFilters.isEmpty()) {
final List<ObjectPair<String, Long>> filterDurations = new ArrayList<>();
final AtomicLong skippedWithSameCount = new AtomicLong(0L);
final AtomicLong skippedWithLowerCount = new AtomicLong(0L);
getMostCommonElements(mostExpensiveFilters, filterDurations, displayCount, skippedWithSameCount, skippedWithLowerCount);
out();
out("Filters for searches with the longest processing times:");
String durationStr = "";
for (final ObjectPair<String, Long> p : filterDurations) {
final long durationMicros = p.getSecond();
final double durationMillis = durationMicros / 1_000.0;
durationStr = decimalFormat.format(durationMillis) + " ms";
out(p.getFirst(), ": ", durationStr);
}
if (skippedWithSameCount.get() > 0L) {
out("{ Skipped " + skippedWithSameCount.get() + " additional " + getSingularOrPlural(skippedWithSameCount.get(), "filter", "filters") + " with a duration of " + durationStr + " }");
}
if (skippedWithLowerCount.get() > 0L) {
out("{ Skipped " + skippedWithLowerCount.get() + " additional " + getSingularOrPlural(skippedWithLowerCount.get(), "filter", "filters") + " with a duration that is less than " + durationStr + " }");
}
}
final long totalUncached = numUncachedAdds + numUncachedBinds + numUncachedCompares + numUncachedDeletes + numUncachedExtended + numUncachedModifies + numUncachedModifyDNs + numUncachedSearches;
if (totalUncached > 0L) {
out();
out("Operations accessing uncached data:");
printUncached("Add", numUncachedAdds, numAdds);
printUncached("Bind", numUncachedBinds, numBinds);
printUncached("Compare", numUncachedCompares, numCompares);
printUncached("Delete", numUncachedDeletes, numDeletes);
printUncached("Extended", numUncachedExtended, numExtended);
printUncached("Modify", numUncachedModifies, numModifies);
printUncached("Modify DN", numUncachedModifyDNs, numModifyDNs);
printUncached("Search", numUncachedSearches, numSearches);
}
return ResultCode.SUCCESS;
}
Aggregations