Examples with JSONAccessLogReader com.unboundid.ldap.sdk.unboundidds.logs.v2.json.JSONAccessLogReader used on opensource projects

Example 1 with JSONAccessLogReader

use of com.unboundid.ldap.sdk.unboundidds.logs.v2.json.JSONAccessLogReader 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;
}