001/* 002 * Copyright 2009-2018 Ping Identity Corporation 003 * All Rights Reserved. 004 */ 005/* 006 * Copyright (C) 2015-2018 Ping Identity Corporation 007 * 008 * This program is free software; you can redistribute it and/or modify 009 * it under the terms of the GNU General Public License (GPLv2 only) 010 * or the terms of the GNU Lesser General Public License (LGPLv2.1 only) 011 * as published by the Free Software Foundation. 012 * 013 * This program is distributed in the hope that it will be useful, 014 * but WITHOUT ANY WARRANTY; without even the implied warranty of 015 * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the 016 * GNU General Public License for more details. 017 * 018 * You should have received a copy of the GNU General Public License 019 * along with this program; if not, see <http://www.gnu.org/licenses>. 020 */ 021package com.unboundid.ldap.sdk.unboundidds.examples; 022 023 024 025import java.io.File; 026import java.io.FileInputStream; 027import java.io.InputStream; 028import java.io.InputStreamReader; 029import java.io.IOException; 030import java.io.OutputStream; 031import java.io.Serializable; 032import java.text.DecimalFormat; 033import java.util.ArrayList; 034import java.util.HashMap; 035import java.util.HashSet; 036import java.util.Iterator; 037import java.util.LinkedHashMap; 038import java.util.List; 039import java.util.Map; 040import java.util.TreeMap; 041import java.util.concurrent.atomic.AtomicLong; 042import java.util.zip.GZIPInputStream; 043import javax.crypto.BadPaddingException; 044 045import com.unboundid.ldap.sdk.Filter; 046import com.unboundid.ldap.sdk.LDAPException; 047import com.unboundid.ldap.sdk.ResultCode; 048import com.unboundid.ldap.sdk.SearchScope; 049import com.unboundid.ldap.sdk.Version; 050import com.unboundid.ldap.sdk.unboundidds.logs.AbandonRequestAccessLogMessage; 051import com.unboundid.ldap.sdk.unboundidds.logs.AccessLogMessage; 052import com.unboundid.ldap.sdk.unboundidds.logs.AccessLogReader; 053import com.unboundid.ldap.sdk.unboundidds.logs.AddResultAccessLogMessage; 054import com.unboundid.ldap.sdk.unboundidds.logs.BindResultAccessLogMessage; 055import com.unboundid.ldap.sdk.unboundidds.logs.CompareResultAccessLogMessage; 056import com.unboundid.ldap.sdk.unboundidds.logs.ConnectAccessLogMessage; 057import com.unboundid.ldap.sdk.unboundidds.logs.DeleteResultAccessLogMessage; 058import com.unboundid.ldap.sdk.unboundidds.logs.DisconnectAccessLogMessage; 059import com.unboundid.ldap.sdk.unboundidds.logs.ExtendedRequestAccessLogMessage; 060import com.unboundid.ldap.sdk.unboundidds.logs.ExtendedResultAccessLogMessage; 061import com.unboundid.ldap.sdk.unboundidds.logs.LogException; 062import com.unboundid.ldap.sdk.unboundidds.logs.ModifyDNResultAccessLogMessage; 063import com.unboundid.ldap.sdk.unboundidds.logs.ModifyResultAccessLogMessage; 064import com.unboundid.ldap.sdk.unboundidds.logs.OperationAccessLogMessage; 065import com.unboundid.ldap.sdk.unboundidds.logs.SearchRequestAccessLogMessage; 066import com.unboundid.ldap.sdk.unboundidds.logs.SearchResultAccessLogMessage; 067import com.unboundid.ldap.sdk.unboundidds.logs.UnbindRequestAccessLogMessage; 068import com.unboundid.ldap.sdk.unboundidds.tools.ToolUtils; 069import com.unboundid.util.CommandLineTool; 070import com.unboundid.util.Debug; 071import com.unboundid.util.NotMutable; 072import com.unboundid.util.ObjectPair; 073import com.unboundid.util.ReverseComparator; 074import com.unboundid.util.StaticUtils; 075import com.unboundid.util.ThreadSafety; 076import com.unboundid.util.ThreadSafetyLevel; 077import com.unboundid.util.args.ArgumentException; 078import com.unboundid.util.args.ArgumentParser; 079import com.unboundid.util.args.BooleanArgument; 080import com.unboundid.util.args.FileArgument; 081 082 083 084/** 085 * This class provides a tool that may be used to read and summarize the 086 * contents of one or more access log files from Ping Identity, UnboundID and 087 * Nokia/Alcatel-Lucent 8661 server products. 088 * <BR> 089 * <BLOCKQUOTE> 090 * <B>NOTE:</B> This class, and other classes within the 091 * {@code com.unboundid.ldap.sdk.unboundidds} package structure, are only 092 * supported for use against Ping Identity, UnboundID, and 093 * Nokia/Alcatel-Lucent 8661 server products. These classes provide support 094 * for proprietary functionality or for external specifications that are not 095 * considered stable or mature enough to be guaranteed to work in an 096 * interoperable way with other types of LDAP servers. 097 * </BLOCKQUOTE> 098 * Information that will be reported includes: 099 * <UL> 100 * <LI>The total length of time covered by the log files.</LI> 101 * <LI>The number of connections established and disconnected, the addresses 102 * of the most commonly-connecting clients, and the average rate of 103 * connects and disconnects per second.</LI> 104 * <LI>The number of operations processed, overall and by operation type, 105 * and the average rate of operations per second.</LI> 106 * <LI>The average duration for operations processed, overall and by operation 107 * type.</LI> 108 * <LI>A breakdown of operation processing times into a number of predefined 109 * categories (less than 1ms, between 1ms and 2ms, between 2ms and 3ms, 110 * between 3ms and 5ms, between 5ms and 10ms, between 10ms and 20ms, 111 * between 20ms and 30ms, between 30ms and 50ms, between 50ms and 100ms, 112 * between 100ms and 1000ms, and over 1000ms).</LI> 113 * <LI>A breakdown of the most common result codes for each type of operation 114 * and their relative frequencies.</LI> 115 * <LI>The most common types of extended requests processed and their 116 * relative frequencies.</LI> 117 * <LI>The number of unindexed search operations processed.</LI> 118 * <LI>A breakdown of the relative frequencies for each type of search 119 * scope.</LI> 120 * <LI>The most common types of search filters used for search 121 * operations and their relative frequencies.</LI> 122 * </UL> 123 * It is designed to work with access log files using either the default log 124 * format with separate request and response messages, as well as log files 125 * in which the request and response details have been combined on the same 126 * line. The log files to be processed should be provided as command-line 127 * arguments. 128 * <BR><BR> 129 * The APIs demonstrated by this example include: 130 * <UL> 131 * <LI>Access log parsing (from the 132 * {@code com.unboundid.ldap.sdk.unboundidds.logs} package)</LI> 133 * <LI>Argument parsing (from the {@code com.unboundid.util.args} 134 * package)</LI> 135 * </UL> 136 */ 137@NotMutable() 138@ThreadSafety(level=ThreadSafetyLevel.NOT_THREADSAFE) 139public final class SummarizeAccessLog 140 extends CommandLineTool 141 implements Serializable 142{ 143 /** 144 * The serial version UID for this serializable class. 145 */ 146 private static final long serialVersionUID = 7189168366509887130L; 147 148 149 150 // Variables used for accessing argument information. 151 private ArgumentParser argumentParser; 152 153 // An argument which may be used to indicate that the log files are 154 // compressed. 155 private BooleanArgument isCompressed; 156 157 // An argument used to specify the encryption passphrase. 158 private FileArgument encryptionPassphraseFile; 159 160 // The decimal format that will be used for this class. 161 private final DecimalFormat decimalFormat; 162 163 // The total duration for log content, in milliseconds. 164 private long logDurationMillis; 165 166 // The total processing time for each type of operation. 167 private double addProcessingDuration; 168 private double bindProcessingDuration; 169 private double compareProcessingDuration; 170 private double deleteProcessingDuration; 171 private double extendedProcessingDuration; 172 private double modifyProcessingDuration; 173 private double modifyDNProcessingDuration; 174 private double searchProcessingDuration; 175 176 // A variable used for counting the number of messages of each type. 177 private long numAbandons; 178 private long numAdds; 179 private long numBinds; 180 private long numCompares; 181 private long numConnects; 182 private long numDeletes; 183 private long numDisconnects; 184 private long numExtended; 185 private long numModifies; 186 private long numModifyDNs; 187 private long numNonBaseSearches; 188 private long numSearches; 189 private long numUnbinds; 190 191 // The number of operations of each type that accessed uncached data. 192 private long numUncachedAdds; 193 private long numUncachedBinds; 194 private long numUncachedCompares; 195 private long numUncachedDeletes; 196 private long numUncachedExtended; 197 private long numUncachedModifies; 198 private long numUncachedModifyDNs; 199 private long numUncachedSearches; 200 201 // The number of unindexed searches processed within the server. 202 private long numUnindexedAttempts; 203 private long numUnindexedFailed; 204 private long numUnindexedSuccessful; 205 206 // Variables used for maintaining counts for common types of information. 207 private final HashMap<Long,AtomicLong> searchEntryCounts; 208 private final HashMap<ResultCode,AtomicLong> addResultCodes; 209 private final HashMap<ResultCode,AtomicLong> bindResultCodes; 210 private final HashMap<ResultCode,AtomicLong> compareResultCodes; 211 private final HashMap<ResultCode,AtomicLong> deleteResultCodes; 212 private final HashMap<ResultCode,AtomicLong> extendedResultCodes; 213 private final HashMap<ResultCode,AtomicLong> modifyResultCodes; 214 private final HashMap<ResultCode,AtomicLong> modifyDNResultCodes; 215 private final HashMap<ResultCode,AtomicLong> searchResultCodes; 216 private final HashMap<SearchScope,AtomicLong> searchScopes; 217 private final HashMap<String,AtomicLong> clientAddresses; 218 private final HashMap<String,AtomicLong> clientConnectionPolicies; 219 private final HashMap<String,AtomicLong> disconnectReasons; 220 private final HashMap<String,AtomicLong> extendedOperations; 221 private final HashMap<String,AtomicLong> filterTypes; 222 private final HashSet<String> processedRequests; 223 private final LinkedHashMap<Long,AtomicLong> addProcessingTimes; 224 private final LinkedHashMap<Long,AtomicLong> bindProcessingTimes; 225 private final LinkedHashMap<Long,AtomicLong> compareProcessingTimes; 226 private final LinkedHashMap<Long,AtomicLong> deleteProcessingTimes; 227 private final LinkedHashMap<Long,AtomicLong> extendedProcessingTimes; 228 private final LinkedHashMap<Long,AtomicLong> modifyProcessingTimes; 229 private final LinkedHashMap<Long,AtomicLong> modifyDNProcessingTimes; 230 private final LinkedHashMap<Long,AtomicLong> searchProcessingTimes; 231 232 233 234 /** 235 * Parse the provided command line arguments and perform the appropriate 236 * processing. 237 * 238 * @param args The command line arguments provided to this program. 239 */ 240 public static void main(final String[] args) 241 { 242 final ResultCode resultCode = main(args, System.out, System.err); 243 if (resultCode != ResultCode.SUCCESS) 244 { 245 System.exit(resultCode.intValue()); 246 } 247 } 248 249 250 251 /** 252 * Parse the provided command line arguments and perform the appropriate 253 * processing. 254 * 255 * @param args The command line arguments provided to this program. 256 * @param outStream The output stream to which standard out should be 257 * written. It may be {@code null} if output should be 258 * suppressed. 259 * @param errStream The output stream to which standard error should be 260 * written. It may be {@code null} if error messages 261 * should be suppressed. 262 * 263 * @return A result code indicating whether the processing was successful. 264 */ 265 public static ResultCode main(final String[] args, 266 final OutputStream outStream, 267 final OutputStream errStream) 268 { 269 final SummarizeAccessLog summarizer = 270 new SummarizeAccessLog(outStream, errStream); 271 return summarizer.runTool(args); 272 } 273 274 275 276 /** 277 * Creates a new instance of this tool. 278 * 279 * @param outStream The output stream to which standard out should be 280 * written. It may be {@code null} if output should be 281 * suppressed. 282 * @param errStream The output stream to which standard error should be 283 * written. It may be {@code null} if error messages 284 * should be suppressed. 285 */ 286 public SummarizeAccessLog(final OutputStream outStream, 287 final OutputStream errStream) 288 { 289 super(outStream, errStream); 290 291 decimalFormat = new DecimalFormat("0.000"); 292 293 logDurationMillis = 0L; 294 295 addProcessingDuration = 0.0; 296 bindProcessingDuration = 0.0; 297 compareProcessingDuration = 0.0; 298 deleteProcessingDuration = 0.0; 299 extendedProcessingDuration = 0.0; 300 modifyProcessingDuration = 0.0; 301 modifyDNProcessingDuration = 0.0; 302 searchProcessingDuration = 0.0; 303 304 numAbandons = 0L; 305 numAdds = 0L; 306 numBinds = 0L; 307 numCompares = 0L; 308 numConnects = 0L; 309 numDeletes = 0L; 310 numDisconnects = 0L; 311 numExtended = 0L; 312 numModifies = 0L; 313 numModifyDNs = 0L; 314 numNonBaseSearches = 0L; 315 numSearches = 0L; 316 numUnbinds = 0L; 317 318 numUncachedAdds = 0L; 319 numUncachedBinds = 0L; 320 numUncachedCompares = 0L; 321 numUncachedDeletes = 0L; 322 numUncachedExtended = 0L; 323 numUncachedModifies = 0L; 324 numUncachedModifyDNs = 0L; 325 numUncachedSearches = 0L; 326 327 searchEntryCounts = new HashMap<>(10); 328 addResultCodes = new HashMap<>(10); 329 bindResultCodes = new HashMap<>(10); 330 compareResultCodes = new HashMap<>(10); 331 deleteResultCodes = new HashMap<>(10); 332 extendedResultCodes = new HashMap<>(10); 333 modifyResultCodes = new HashMap<>(10); 334 modifyDNResultCodes = new HashMap<>(10); 335 searchResultCodes = new HashMap<>(10); 336 searchScopes = new HashMap<>(4); 337 clientAddresses = new HashMap<>(100); 338 clientConnectionPolicies = new HashMap<>(100); 339 disconnectReasons = new HashMap<>(100); 340 extendedOperations = new HashMap<>(10); 341 filterTypes = new HashMap<>(100); 342 processedRequests = new HashSet<>(100); 343 addProcessingTimes = new LinkedHashMap<>(11); 344 bindProcessingTimes = new LinkedHashMap<>(11); 345 compareProcessingTimes = new LinkedHashMap<>(11); 346 deleteProcessingTimes = new LinkedHashMap<>(11); 347 extendedProcessingTimes = new LinkedHashMap<>(11); 348 modifyProcessingTimes = new LinkedHashMap<>(11); 349 modifyDNProcessingTimes = new LinkedHashMap<>(11); 350 searchProcessingTimes = new LinkedHashMap<>(11); 351 352 populateProcessingTimeMap(addProcessingTimes); 353 populateProcessingTimeMap(bindProcessingTimes); 354 populateProcessingTimeMap(compareProcessingTimes); 355 populateProcessingTimeMap(deleteProcessingTimes); 356 populateProcessingTimeMap(extendedProcessingTimes); 357 populateProcessingTimeMap(modifyProcessingTimes); 358 populateProcessingTimeMap(modifyDNProcessingTimes); 359 populateProcessingTimeMap(searchProcessingTimes); 360 } 361 362 363 364 /** 365 * Retrieves the name for this tool. 366 * 367 * @return The name for this tool. 368 */ 369 @Override() 370 public String getToolName() 371 { 372 return "summarize-access-log"; 373 } 374 375 376 377 /** 378 * Retrieves the description for this tool. 379 * 380 * @return The description for this tool. 381 */ 382 @Override() 383 public String getToolDescription() 384 { 385 return "Examine one or more access log files from Ping Identity, " + 386 "UnboundID, or Nokia/Alcatel-Lucent 8661 server products to display " + 387 "a number of metrics about operations processed within the server."; 388 } 389 390 391 392 /** 393 * Retrieves the version string for this tool. 394 * 395 * @return The version string for this tool. 396 */ 397 @Override() 398 public String getToolVersion() 399 { 400 return Version.NUMERIC_VERSION_STRING; 401 } 402 403 404 405 /** 406 * Retrieves the minimum number of unnamed trailing arguments that are 407 * required. 408 * 409 * @return One, to indicate that at least one trailing argument (representing 410 * the path to an access log file) must be provided. 411 */ 412 @Override() 413 public int getMinTrailingArguments() 414 { 415 return 1; 416 } 417 418 419 420 /** 421 * Retrieves the maximum number of unnamed trailing arguments that may be 422 * provided for this tool. 423 * 424 * @return The maximum number of unnamed trailing arguments that may be 425 * provided for this tool. 426 */ 427 @Override() 428 public int getMaxTrailingArguments() 429 { 430 return -1; 431 } 432 433 434 435 /** 436 * Retrieves a placeholder string that should be used for trailing arguments 437 * in the usage information for this tool. 438 * 439 * @return A placeholder string that should be used for trailing arguments in 440 * the usage information for this tool. 441 */ 442 @Override() 443 public String getTrailingArgumentsPlaceholder() 444 { 445 return "{path}"; 446 } 447 448 449 450 /** 451 * Indicates whether this tool should provide support for an interactive mode, 452 * in which the tool offers a mode in which the arguments can be provided in 453 * a text-driven menu rather than requiring them to be given on the command 454 * line. If interactive mode is supported, it may be invoked using the 455 * "--interactive" argument. Alternately, if interactive mode is supported 456 * and {@link #defaultsToInteractiveMode()} returns {@code true}, then 457 * interactive mode may be invoked by simply launching the tool without any 458 * arguments. 459 * 460 * @return {@code true} if this tool supports interactive mode, or 461 * {@code false} if not. 462 */ 463 @Override() 464 public boolean supportsInteractiveMode() 465 { 466 return true; 467 } 468 469 470 471 /** 472 * Indicates whether this tool defaults to launching in interactive mode if 473 * the tool is invoked without any command-line arguments. This will only be 474 * used if {@link #supportsInteractiveMode()} returns {@code true}. 475 * 476 * @return {@code true} if this tool defaults to using interactive mode if 477 * launched without any command-line arguments, or {@code false} if 478 * not. 479 */ 480 @Override() 481 public boolean defaultsToInteractiveMode() 482 { 483 return true; 484 } 485 486 487 488 /** 489 * Indicates whether this tool should provide arguments for redirecting output 490 * to a file. If this method returns {@code true}, then the tool will offer 491 * an "--outputFile" argument that will specify the path to a file to which 492 * all standard output and standard error content will be written, and it will 493 * also offer a "--teeToStandardOut" argument that can only be used if the 494 * "--outputFile" argument is present and will cause all output to be written 495 * to both the specified output file and to standard output. 496 * 497 * @return {@code true} if this tool should provide arguments for redirecting 498 * output to a file, or {@code false} if not. 499 */ 500 @Override() 501 protected boolean supportsOutputFile() 502 { 503 return true; 504 } 505 506 507 508 /** 509 * Indicates whether this tool supports the use of a properties file for 510 * specifying default values for arguments that aren't specified on the 511 * command line. 512 * 513 * @return {@code true} if this tool supports the use of a properties file 514 * for specifying default values for arguments that aren't specified 515 * on the command line, or {@code false} if not. 516 */ 517 @Override() 518 public boolean supportsPropertiesFile() 519 { 520 return true; 521 } 522 523 524 525 /** 526 * Adds the command-line arguments supported for use with this tool to the 527 * provided argument parser. The tool may need to retain references to the 528 * arguments (and/or the argument parser, if trailing arguments are allowed) 529 * to it in order to obtain their values for use in later processing. 530 * 531 * @param parser The argument parser to which the arguments are to be added. 532 * 533 * @throws ArgumentException If a problem occurs while adding any of the 534 * tool-specific arguments to the provided 535 * argument parser. 536 */ 537 @Override() 538 public void addToolArguments(final ArgumentParser parser) 539 throws ArgumentException 540 { 541 // We need to save a reference to the argument parser so that we can get 542 // the trailing arguments later. 543 argumentParser = parser; 544 545 // Add an argument that makes it possible to read a compressed log file. 546 // Note that this argument is no longer needed for dealing with compressed 547 // files, since the tool will automatically detect whether a file is 548 // compressed. However, the argument is still provided for the purpose of 549 // backward compatibility. 550 String description = "Indicates that the log file is compressed."; 551 isCompressed = new BooleanArgument('c', "isCompressed", description); 552 isCompressed.addLongIdentifier("is-compressed", true); 553 isCompressed.addLongIdentifier("compressed", true); 554 isCompressed.setHidden(true); 555 parser.addArgument(isCompressed); 556 557 558 // Add an argument that indicates that the tool should read the encryption 559 // passphrase from a file. 560 description = "Indicates that the log file is encrypted and that the " + 561 "encryption passphrase is contained in the specified file. If " + 562 "the log data is encrypted and this argument is not provided, then " + 563 "the tool will interactively prompt for the encryption passphrase."; 564 encryptionPassphraseFile = new FileArgument(null, 565 "encryptionPassphraseFile", false, 1, null, description, true, true, 566 true, false); 567 encryptionPassphraseFile.addLongIdentifier("encryption-passphrase-file", 568 true); 569 encryptionPassphraseFile.addLongIdentifier("encryptionPasswordFile", true); 570 encryptionPassphraseFile.addLongIdentifier("encryption-password-file", 571 true); 572 parser.addArgument(encryptionPassphraseFile); 573 } 574 575 576 577 /** 578 * Performs any necessary processing that should be done to ensure that the 579 * provided set of command-line arguments were valid. This method will be 580 * called after the basic argument parsing has been performed and immediately 581 * before the {@link CommandLineTool#doToolProcessing} method is invoked. 582 * 583 * @throws ArgumentException If there was a problem with the command-line 584 * arguments provided to this program. 585 */ 586 @Override() 587 public void doExtendedArgumentValidation() 588 throws ArgumentException 589 { 590 // Make sure that at least one access log file path was provided. 591 final List<String> trailingArguments = 592 argumentParser.getTrailingArguments(); 593 if ((trailingArguments == null) || trailingArguments.isEmpty()) 594 { 595 throw new ArgumentException("No access log file paths were provided."); 596 } 597 } 598 599 600 601 /** 602 * Performs the core set of processing for this tool. 603 * 604 * @return A result code that indicates whether the processing completed 605 * successfully. 606 */ 607 @Override() 608 public ResultCode doToolProcessing() 609 { 610 String encryptionPassphrase = null; 611 if (encryptionPassphraseFile.isPresent()) 612 { 613 try 614 { 615 encryptionPassphrase = ToolUtils.readEncryptionPassphraseFromFile( 616 encryptionPassphraseFile.getValue()); 617 } 618 catch (final LDAPException e) 619 { 620 Debug.debugException(e); 621 err(e.getMessage()); 622 return e.getResultCode(); 623 } 624 } 625 626 627 long logLines = 0L; 628 for (final String path : argumentParser.getTrailingArguments()) 629 { 630 final File f = new File(path); 631 out("Examining access log ", f.getAbsolutePath()); 632 AccessLogReader reader = null; 633 InputStream inputStream = null; 634 try 635 { 636 inputStream = new FileInputStream(f); 637 638 final ObjectPair<InputStream,String> p = 639 ToolUtils.getPossiblyPassphraseEncryptedInputStream(inputStream, 640 encryptionPassphrase, 641 (! encryptionPassphraseFile.isPresent()), 642 "Log file '" + path + "' is encrypted. Please enter the " + 643 "encryption passphrase:", 644 "ERROR: The provided passphrase was incorrect.", 645 getOut(), getErr()); 646 inputStream = p.getFirst(); 647 if ((p.getSecond() != null) && (encryptionPassphrase == null)) 648 { 649 encryptionPassphrase = p.getSecond(); 650 } 651 652 if (isCompressed.isPresent()) 653 { 654 inputStream = new GZIPInputStream(inputStream); 655 } 656 else 657 { 658 inputStream = 659 ToolUtils.getPossiblyGZIPCompressedInputStream(inputStream); 660 } 661 662 reader = new AccessLogReader(new InputStreamReader(inputStream)); 663 } 664 catch (final Exception e) 665 { 666 Debug.debugException(e); 667 err("Unable to open access log file ", f.getAbsolutePath(), ": ", 668 StaticUtils.getExceptionMessage(e)); 669 return ResultCode.LOCAL_ERROR; 670 } 671 finally 672 { 673 if ((reader == null) && (inputStream != null)) 674 { 675 try 676 { 677 inputStream.close(); 678 } 679 catch (final Exception e) 680 { 681 Debug.debugException(e); 682 } 683 } 684 } 685 686 long startTime = 0L; 687 long stopTime = 0L; 688 689 while (true) 690 { 691 final AccessLogMessage msg; 692 try 693 { 694 msg = reader.read(); 695 } 696 catch (final IOException ioe) 697 { 698 Debug.debugException(ioe); 699 err("Error reading from access log file ", f.getAbsolutePath(), 700 ": ", StaticUtils.getExceptionMessage(ioe)); 701 702 if ((ioe.getCause() != null) && 703 (ioe.getCause() instanceof BadPaddingException)) 704 { 705 err("This error is likely because the log is encrypted and the " + 706 "server still has the log file open. It is recommended " + 707 "that you only try to examine encrypted logs after they " + 708 "have been rotated. You can use the rotate-log tool to " + 709 "force a rotation at any time. Attempting to proceed with " + 710 "just the data that was successfully read."); 711 break; 712 } 713 else 714 { 715 return ResultCode.LOCAL_ERROR; 716 } 717 } 718 catch (final LogException le) 719 { 720 Debug.debugException(le); 721 err("Encountered an error while attempting to parse a line in" + 722 "access log file ", f.getAbsolutePath(), ": ", 723 StaticUtils.getExceptionMessage(le)); 724 continue; 725 } 726 727 if (msg == null) 728 { 729 break; 730 } 731 732 logLines++; 733 stopTime = msg.getTimestamp().getTime(); 734 if (startTime == 0L) 735 { 736 startTime = stopTime; 737 } 738 739 switch (msg.getMessageType()) 740 { 741 case CONNECT: 742 processConnect((ConnectAccessLogMessage) msg); 743 break; 744 case DISCONNECT: 745 processDisconnect((DisconnectAccessLogMessage) msg); 746 break; 747 case REQUEST: 748 switch (((OperationAccessLogMessage) msg).getOperationType()) 749 { 750 case ABANDON: 751 processAbandonRequest((AbandonRequestAccessLogMessage) msg); 752 break; 753 case EXTENDED: 754 processExtendedRequest((ExtendedRequestAccessLogMessage) msg); 755 break; 756 case SEARCH: 757 processSearchRequest((SearchRequestAccessLogMessage) msg); 758 break; 759 case UNBIND: 760 processUnbindRequest((UnbindRequestAccessLogMessage) msg); 761 break; 762 } 763 break; 764 case RESULT: 765 switch (((OperationAccessLogMessage) msg).getOperationType()) 766 { 767 case ADD: 768 processAddResult((AddResultAccessLogMessage) msg); 769 break; 770 case BIND: 771 processBindResult((BindResultAccessLogMessage) msg); 772 break; 773 case COMPARE: 774 processCompareResult((CompareResultAccessLogMessage) msg); 775 break; 776 case DELETE: 777 processDeleteResult((DeleteResultAccessLogMessage) msg); 778 break; 779 case EXTENDED: 780 processExtendedResult((ExtendedResultAccessLogMessage) msg); 781 break; 782 case MODIFY: 783 processModifyResult((ModifyResultAccessLogMessage) msg); 784 break; 785 case MODDN: 786 processModifyDNResult((ModifyDNResultAccessLogMessage) msg); 787 break; 788 case SEARCH: 789 processSearchResult((SearchResultAccessLogMessage) msg); 790 break; 791 } 792 break; 793 794 case ASSURANCE_COMPLETE: 795 case CLIENT_CERTIFICATE: 796 case ENTRY_REBALANCING_REQUEST: 797 case ENTRY_REBALANCING_RESULT: 798 case FORWARD: 799 case FORWARD_FAILED: 800 case ENTRY: 801 case REFERENCE: 802 default: 803 // Nothing needs to be done for these message types. 804 } 805 } 806 807 try 808 { 809 reader.close(); 810 } 811 catch (final Exception e) 812 { 813 Debug.debugException(e); 814 } 815 logDurationMillis += (stopTime - startTime); 816 } 817 818 819 final int numFiles = argumentParser.getTrailingArguments().size(); 820 out(); 821 out("Examined ", logLines, " lines in ", numFiles, 822 ((numFiles == 1) ? " file" : " files"), 823 " covering a total duration of ", 824 StaticUtils.millisToHumanReadableDuration(logDurationMillis)); 825 if (logLines == 0) 826 { 827 return ResultCode.SUCCESS; 828 } 829 830 out(); 831 832 final double logDurationSeconds = logDurationMillis / 1000.0; 833 final double connectsPerSecond = numConnects / logDurationSeconds; 834 final double disconnectsPerSecond = numDisconnects / logDurationSeconds; 835 836 out("Total connections established: ", numConnects, " (", 837 decimalFormat.format(connectsPerSecond), "/second)"); 838 out("Total disconnects: ", numDisconnects, " (", 839 decimalFormat.format(disconnectsPerSecond), "/second)"); 840 841 if (! clientAddresses.isEmpty()) 842 { 843 out(); 844 final List<ObjectPair<String,Long>> connectCounts = 845 getMostCommonElements(clientAddresses, 20); 846 out("Most common client addresses:"); 847 for (final ObjectPair<String,Long> p : connectCounts) 848 { 849 final long count = p.getSecond(); 850 final double percent = 100.0 * count / numConnects; 851 852 out(p.getFirst(), ": ", count, " (", decimalFormat.format(percent), 853 ")"); 854 } 855 } 856 857 if (! clientConnectionPolicies.isEmpty()) 858 { 859 long totalCCPs = 0; 860 for (final AtomicLong l : clientConnectionPolicies.values()) 861 { 862 totalCCPs += l.get(); 863 } 864 865 final List<ObjectPair<String,Long>> reasonCounts = 866 getMostCommonElements(clientConnectionPolicies, 20); 867 868 out(); 869 out("Most common client connection policies:"); 870 for (final ObjectPair<String,Long> p : reasonCounts) 871 { 872 final long count = p.getSecond(); 873 final double percent = 100.0 * count / totalCCPs; 874 out(p.getFirst(), ": ", p.getSecond(), " (", 875 decimalFormat.format(percent), "%)"); 876 } 877 } 878 879 if (! disconnectReasons.isEmpty()) 880 { 881 final List<ObjectPair<String,Long>> reasonCounts = 882 getMostCommonElements(disconnectReasons, 20); 883 884 out(); 885 out("Most common disconnect reasons:"); 886 for (final ObjectPair<String,Long> p : reasonCounts) 887 { 888 final long count = p.getSecond(); 889 final double percent = 100.0 * count / numDisconnects; 890 out(p.getFirst(), ": ", p.getSecond(), " (", 891 decimalFormat.format(percent), "%)"); 892 } 893 } 894 895 final long totalOps = numAbandons + numAdds + numBinds + numCompares + 896 numDeletes + numExtended + numModifies + numModifyDNs + numSearches + 897 numUnbinds; 898 if (totalOps > 0) 899 { 900 final double percentAbandon = 100.0 * numAbandons / totalOps; 901 final double percentAdd = 100.0 * numAdds / totalOps; 902 final double percentBind = 100.0 * numBinds / totalOps; 903 final double percentCompare = 100.0 * numCompares / totalOps; 904 final double percentDelete = 100.0 * numDeletes / totalOps; 905 final double percentExtended = 100.0 * numExtended / totalOps; 906 final double percentModify = 100.0 * numModifies / totalOps; 907 final double percentModifyDN = 100.0 * numModifyDNs / totalOps; 908 final double percentSearch = 100.0 * numSearches / totalOps; 909 final double percentUnbind = 100.0 * numUnbinds / totalOps; 910 911 final double abandonsPerSecond = numAbandons / logDurationSeconds; 912 final double addsPerSecond = numAdds / logDurationSeconds; 913 final double bindsPerSecond = numBinds / logDurationSeconds; 914 final double comparesPerSecond = numCompares / logDurationSeconds; 915 final double deletesPerSecond = numDeletes / logDurationSeconds; 916 final double extendedPerSecond = numExtended / logDurationSeconds; 917 final double modifiesPerSecond = numModifies / logDurationSeconds; 918 final double modifyDNsPerSecond = numModifyDNs / logDurationSeconds; 919 final double searchesPerSecond = numSearches / logDurationSeconds; 920 final double unbindsPerSecond = numUnbinds / logDurationSeconds; 921 922 out(); 923 out("Total operations examined: ", totalOps); 924 out("Abandon operations examined: ", numAbandons, " (", 925 decimalFormat.format(percentAbandon), "%, ", 926 decimalFormat.format(abandonsPerSecond), "/second)"); 927 out("Add operations examined: ", numAdds, " (", 928 decimalFormat.format(percentAdd), "%, ", 929 decimalFormat.format(addsPerSecond), "/second)"); 930 out("Bind operations examined: ", numBinds, " (", 931 decimalFormat.format(percentBind), "%, ", 932 decimalFormat.format(bindsPerSecond), "/second)"); 933 out("Compare operations examined: ", numCompares, " (", 934 decimalFormat.format(percentCompare), "%, ", 935 decimalFormat.format(comparesPerSecond), "/second)"); 936 out("Delete operations examined: ", numDeletes, " (", 937 decimalFormat.format(percentDelete), "%, ", 938 decimalFormat.format(deletesPerSecond), "/second)"); 939 out("Extended operations examined: ", numExtended, " (", 940 decimalFormat.format(percentExtended), "%, ", 941 decimalFormat.format(extendedPerSecond), "/second)"); 942 out("Modify operations examined: ", numModifies, " (", 943 decimalFormat.format(percentModify), "%, ", 944 decimalFormat.format(modifiesPerSecond), "/second)"); 945 out("Modify DN operations examined: ", numModifyDNs, " (", 946 decimalFormat.format(percentModifyDN), "%, ", 947 decimalFormat.format(modifyDNsPerSecond), "/second)"); 948 out("Search operations examined: ", numSearches, " (", 949 decimalFormat.format(percentSearch), "%, ", 950 decimalFormat.format(searchesPerSecond), "/second)"); 951 out("Unbind operations examined: ", numUnbinds, " (", 952 decimalFormat.format(percentUnbind), "%, ", 953 decimalFormat.format(unbindsPerSecond), "/second)"); 954 955 final double totalProcessingDuration = addProcessingDuration + 956 bindProcessingDuration + compareProcessingDuration + 957 deleteProcessingDuration + extendedProcessingDuration + 958 modifyProcessingDuration + modifyDNProcessingDuration + 959 searchProcessingDuration; 960 961 out(); 962 out("Average operation processing duration: ", 963 decimalFormat.format(totalProcessingDuration / totalOps), "ms"); 964 965 if (numAdds > 0) 966 { 967 out("Average add operation processing duration: ", 968 decimalFormat.format(addProcessingDuration / numAdds), "ms"); 969 } 970 971 if (numBinds > 0) 972 { 973 out("Average bind operation processing duration: ", 974 decimalFormat.format(bindProcessingDuration / numBinds), "ms"); 975 } 976 977 if (numCompares > 0) 978 { 979 out("Average compare operation processing duration: ", 980 decimalFormat.format(compareProcessingDuration / numCompares), 981 "ms"); 982 } 983 984 if (numDeletes > 0) 985 { 986 out("Average delete operation processing duration: ", 987 decimalFormat.format(deleteProcessingDuration / numDeletes), "ms"); 988 } 989 990 if (numExtended > 0) 991 { 992 out("Average extended operation processing duration: ", 993 decimalFormat.format(extendedProcessingDuration / numExtended), 994 "ms"); 995 } 996 997 if (numModifies > 0) 998 { 999 out("Average modify operation processing duration: ", 1000 decimalFormat.format(modifyProcessingDuration / numModifies), "ms"); 1001 } 1002 1003 if (numModifyDNs > 0) 1004 { 1005 out("Average modify DN operation processing duration: ", 1006 decimalFormat.format(modifyDNProcessingDuration / numModifyDNs), 1007 "ms"); 1008 } 1009 1010 if (numSearches > 0) 1011 { 1012 out("Average search operation processing duration: ", 1013 decimalFormat.format(searchProcessingDuration / numSearches), "ms"); 1014 } 1015 1016 printProcessingTimeHistogram("add", numAdds, addProcessingTimes); 1017 printProcessingTimeHistogram("bind", numBinds, bindProcessingTimes); 1018 printProcessingTimeHistogram("compare", numCompares, 1019 compareProcessingTimes); 1020 printProcessingTimeHistogram("delete", numDeletes, deleteProcessingTimes); 1021 printProcessingTimeHistogram("extended", numExtended, 1022 extendedProcessingTimes); 1023 printProcessingTimeHistogram("modify", numModifies, 1024 modifyProcessingTimes); 1025 printProcessingTimeHistogram("modify DN", numModifyDNs, 1026 modifyDNProcessingTimes); 1027 printProcessingTimeHistogram("search", numSearches, 1028 searchProcessingTimes); 1029 1030 if (! addResultCodes.isEmpty()) 1031 { 1032 final List<ObjectPair<ResultCode,Long>> rcCounts = 1033 getMostCommonElements(addResultCodes, 20); 1034 1035 out(); 1036 out("Most common add operation result codes:"); 1037 for (final ObjectPair<ResultCode,Long> p : rcCounts) 1038 { 1039 final long count = p.getSecond(); 1040 final double percent = 100.0 * count / numAdds; 1041 out(p.getFirst().getName(), ": ", p.getSecond(), " (", 1042 decimalFormat.format(percent), "%)"); 1043 } 1044 } 1045 1046 if (! bindResultCodes.isEmpty()) 1047 { 1048 final List<ObjectPair<ResultCode,Long>> rcCounts = 1049 getMostCommonElements(bindResultCodes, 20); 1050 1051 out(); 1052 out("Most common bind operation result codes:"); 1053 for (final ObjectPair<ResultCode,Long> p : rcCounts) 1054 { 1055 final long count = p.getSecond(); 1056 final double percent = 100.0 * count / numBinds; 1057 out(p.getFirst().getName(), ": ", p.getSecond(), " (", 1058 decimalFormat.format(percent), "%)"); 1059 } 1060 } 1061 1062 if (! compareResultCodes.isEmpty()) 1063 { 1064 final List<ObjectPair<ResultCode,Long>> rcCounts = 1065 getMostCommonElements(compareResultCodes, 20); 1066 1067 out(); 1068 out("Most common compare operation result codes:"); 1069 for (final ObjectPair<ResultCode,Long> p : rcCounts) 1070 { 1071 final long count = p.getSecond(); 1072 final double percent = 100.0 * count / numCompares; 1073 out(p.getFirst().getName(), ": ", p.getSecond(), " (", 1074 decimalFormat.format(percent), "%)"); 1075 } 1076 } 1077 1078 if (! deleteResultCodes.isEmpty()) 1079 { 1080 final List<ObjectPair<ResultCode,Long>> rcCounts = 1081 getMostCommonElements(deleteResultCodes, 20); 1082 1083 out(); 1084 out("Most common delete operation result codes:"); 1085 for (final ObjectPair<ResultCode,Long> p : rcCounts) 1086 { 1087 final long count = p.getSecond(); 1088 final double percent = 100.0 * count / numDeletes; 1089 out(p.getFirst().getName(), ": ", p.getSecond(), " (", 1090 decimalFormat.format(percent), "%)"); 1091 } 1092 } 1093 1094 if (! extendedResultCodes.isEmpty()) 1095 { 1096 final List<ObjectPair<ResultCode,Long>> rcCounts = 1097 getMostCommonElements(extendedResultCodes, 20); 1098 1099 out(); 1100 out("Most common extended operation result codes:"); 1101 for (final ObjectPair<ResultCode,Long> p : rcCounts) 1102 { 1103 final long count = p.getSecond(); 1104 final double percent = 100.0 * count / numExtended; 1105 out(p.getFirst().getName(), ": ", p.getSecond(), " (", 1106 decimalFormat.format(percent), "%)"); 1107 } 1108 } 1109 1110 if (! modifyResultCodes.isEmpty()) 1111 { 1112 final List<ObjectPair<ResultCode,Long>> rcCounts = 1113 getMostCommonElements(modifyResultCodes, 20); 1114 1115 out(); 1116 out("Most common modify operation result codes:"); 1117 for (final ObjectPair<ResultCode,Long> p : rcCounts) 1118 { 1119 final long count = p.getSecond(); 1120 final double percent = 100.0 * count / numModifies; 1121 out(p.getFirst().getName(), ": ", p.getSecond(), " (", 1122 decimalFormat.format(percent), "%)"); 1123 } 1124 } 1125 1126 if (! modifyDNResultCodes.isEmpty()) 1127 { 1128 final List<ObjectPair<ResultCode,Long>> rcCounts = 1129 getMostCommonElements(modifyDNResultCodes, 20); 1130 1131 out(); 1132 out("Most common modify DN operation result codes:"); 1133 for (final ObjectPair<ResultCode,Long> p : rcCounts) 1134 { 1135 final long count = p.getSecond(); 1136 final double percent = 100.0 * count / numModifyDNs; 1137 out(p.getFirst().getName(), ": ", p.getSecond(), " (", 1138 decimalFormat.format(percent), "%)"); 1139 } 1140 } 1141 1142 if (! searchResultCodes.isEmpty()) 1143 { 1144 final List<ObjectPair<ResultCode,Long>> rcCounts = 1145 getMostCommonElements(searchResultCodes, 20); 1146 1147 out(); 1148 out("Most common search operation result codes:"); 1149 for (final ObjectPair<ResultCode,Long> p : rcCounts) 1150 { 1151 final long count = p.getSecond(); 1152 final double percent = 100.0 * count / numSearches; 1153 out(p.getFirst().getName(), ": ", p.getSecond(), " (", 1154 decimalFormat.format(percent), "%)"); 1155 } 1156 } 1157 1158 if (! extendedOperations.isEmpty()) 1159 { 1160 final List<ObjectPair<String,Long>> extOpCounts = 1161 getMostCommonElements(extendedOperations, 20); 1162 1163 out(); 1164 out("Most common extended operation types:"); 1165 for (final ObjectPair<String,Long> p : extOpCounts) 1166 { 1167 final long count = p.getSecond(); 1168 final double percent = 100.0 * count / numExtended; 1169 out(p.getFirst(), ": ", p.getSecond(), " (", 1170 decimalFormat.format(percent), "%)"); 1171 } 1172 } 1173 1174 out(); 1175 out("Number of unindexed search attempts: ", numUnindexedAttempts); 1176 out("Number of successfully-completed unindexed searches: ", 1177 numUnindexedSuccessful); 1178 out("Number of failed unindexed searches: ", numUnindexedFailed); 1179 1180 if (! searchScopes.isEmpty()) 1181 { 1182 final List<ObjectPair<SearchScope,Long>> scopeCounts = 1183 getMostCommonElements(searchScopes, 20); 1184 1185 out(); 1186 out("Most common search scopes:"); 1187 for (final ObjectPair<SearchScope,Long> p : scopeCounts) 1188 { 1189 final long count = p.getSecond(); 1190 final double percent = 100.0 * count / numSearches; 1191 out(p.getFirst().getName(), ": ", p.getSecond(), " (", 1192 decimalFormat.format(percent), "%)"); 1193 } 1194 } 1195 1196 if (! searchEntryCounts.isEmpty()) 1197 { 1198 final List<ObjectPair<Long,Long>> entryCounts = 1199 getMostCommonElements(searchEntryCounts, 20); 1200 1201 out(); 1202 out("Most common search entry counts:"); 1203 for (final ObjectPair<Long,Long> p : entryCounts) 1204 { 1205 final long count = p.getSecond(); 1206 final double percent = 100.0 * count / numSearches; 1207 out(p.getFirst(), ": ", p.getSecond(), " (", 1208 decimalFormat.format(percent), "%)"); 1209 } 1210 } 1211 1212 if (! filterTypes.isEmpty()) 1213 { 1214 final List<ObjectPair<String,Long>> filterCounts = 1215 getMostCommonElements(filterTypes, 20); 1216 1217 out(); 1218 out("Most common generic filters for searches with a non-base scope:"); 1219 for (final ObjectPair<String,Long> p : filterCounts) 1220 { 1221 final long count = p.getSecond(); 1222 final double percent = 100.0 * count / numNonBaseSearches; 1223 out(p.getFirst(), ": ", p.getSecond(), " (", 1224 decimalFormat.format(percent), "%)"); 1225 } 1226 } 1227 } 1228 1229 final long totalUncached = numUncachedAdds + numUncachedBinds + 1230 numUncachedCompares + numUncachedDeletes + numUncachedExtended + 1231 numUncachedModifies + numUncachedModifyDNs + numUncachedSearches; 1232 if (totalUncached > 0L) 1233 { 1234 out(); 1235 out("Operations accessing uncached data:"); 1236 printUncached("Add", numUncachedAdds, numAdds); 1237 printUncached("Bind", numUncachedBinds, numBinds); 1238 printUncached("Compare", numUncachedCompares, numCompares); 1239 printUncached("Delete", numUncachedDeletes, numDeletes); 1240 printUncached("Extended", numUncachedExtended, numExtended); 1241 printUncached("Modify", numUncachedModifies, numModifies); 1242 printUncached("Modify DN", numUncachedModifyDNs, numModifyDNs); 1243 printUncached("Search", numUncachedSearches, numSearches); 1244 } 1245 1246 1247 return ResultCode.SUCCESS; 1248 } 1249 1250 1251 1252 /** 1253 * Retrieves a set of information that may be used to generate example usage 1254 * information. Each element in the returned map should consist of a map 1255 * between an example set of arguments and a string that describes the 1256 * behavior of the tool when invoked with that set of arguments. 1257 * 1258 * @return A set of information that may be used to generate example usage 1259 * information. It may be {@code null} or empty if no example usage 1260 * information is available. 1261 */ 1262 @Override() 1263 public LinkedHashMap<String[],String> getExampleUsages() 1264 { 1265 final LinkedHashMap<String[],String> examples = new LinkedHashMap<>(1); 1266 1267 final String[] args = 1268 { 1269 "/ds/logs/access" 1270 }; 1271 final String description = 1272 "Analyze the contents of the /ds/logs/access access log file."; 1273 examples.put(args, description); 1274 1275 return examples; 1276 } 1277 1278 1279 1280 /** 1281 * Populates the provided processing time map with an initial set of values. 1282 * 1283 * @param m The processing time map to be populated. 1284 */ 1285 private static void populateProcessingTimeMap( 1286 final HashMap<Long,AtomicLong> m) 1287 { 1288 m.put(1L, new AtomicLong(0L)); 1289 m.put(2L, new AtomicLong(0L)); 1290 m.put(3L, new AtomicLong(0L)); 1291 m.put(5L, new AtomicLong(0L)); 1292 m.put(10L, new AtomicLong(0L)); 1293 m.put(20L, new AtomicLong(0L)); 1294 m.put(30L, new AtomicLong(0L)); 1295 m.put(50L, new AtomicLong(0L)); 1296 m.put(100L, new AtomicLong(0L)); 1297 m.put(1000L, new AtomicLong(0L)); 1298 m.put(Long.MAX_VALUE, new AtomicLong(0L)); 1299 } 1300 1301 1302 1303 /** 1304 * Performs any necessary processing for a connect message. 1305 * 1306 * @param m The log message to be processed. 1307 */ 1308 private void processConnect(final ConnectAccessLogMessage m) 1309 { 1310 numConnects++; 1311 1312 final String clientAddr = m.getSourceAddress(); 1313 if (clientAddr != null) 1314 { 1315 AtomicLong count = clientAddresses.get(clientAddr); 1316 if (count == null) 1317 { 1318 count = new AtomicLong(0L); 1319 clientAddresses.put(clientAddr, count); 1320 } 1321 count.incrementAndGet(); 1322 } 1323 1324 final String ccp = m.getClientConnectionPolicy(); 1325 if (ccp != null) 1326 { 1327 AtomicLong l = clientConnectionPolicies.get(ccp); 1328 if (l == null) 1329 { 1330 l = new AtomicLong(0L); 1331 clientConnectionPolicies.put(ccp, l); 1332 } 1333 l.incrementAndGet(); 1334 } 1335 } 1336 1337 1338 1339 /** 1340 * Performs any necessary processing for a disconnect message. 1341 * 1342 * @param m The log message to be processed. 1343 */ 1344 private void processDisconnect(final DisconnectAccessLogMessage m) 1345 { 1346 numDisconnects++; 1347 1348 final String reason = m.getDisconnectReason(); 1349 if (reason != null) 1350 { 1351 AtomicLong l = disconnectReasons.get(reason); 1352 if (l == null) 1353 { 1354 l = new AtomicLong(0L); 1355 disconnectReasons.put(reason, l); 1356 } 1357 l.incrementAndGet(); 1358 } 1359 } 1360 1361 1362 1363 /** 1364 * Performs any necessary processing for an abandon request message. 1365 * 1366 * @param m The log message to be processed. 1367 */ 1368 private void processAbandonRequest(final AbandonRequestAccessLogMessage m) 1369 { 1370 numAbandons++; 1371 } 1372 1373 1374 1375 /** 1376 * Performs any necessary processing for an extended request message. 1377 * 1378 * @param m The log message to be processed. 1379 */ 1380 private void processExtendedRequest(final ExtendedRequestAccessLogMessage m) 1381 { 1382 processedRequests.add(m.getConnectionID() + "-" + m.getOperationID()); 1383 processExtendedRequestInternal(m); 1384 } 1385 1386 1387 1388 /** 1389 * Performs the internal processing for an extended request message. 1390 * 1391 * @param m The log message to be processed. 1392 */ 1393 private void processExtendedRequestInternal( 1394 final ExtendedRequestAccessLogMessage m) 1395 { 1396 final String oid = m.getRequestOID(); 1397 if (oid != null) 1398 { 1399 AtomicLong l = extendedOperations.get(oid); 1400 if (l == null) 1401 { 1402 l = new AtomicLong(0L); 1403 extendedOperations.put(oid, l); 1404 } 1405 l.incrementAndGet(); 1406 } 1407 } 1408 1409 1410 1411 /** 1412 * Performs any necessary processing for a search request message. 1413 * 1414 * @param m The log message to be processed. 1415 */ 1416 private void processSearchRequest(final SearchRequestAccessLogMessage m) 1417 { 1418 processedRequests.add(m.getConnectionID() + "-" + m.getOperationID()); 1419 processSearchRequestInternal(m); 1420 } 1421 1422 1423 1424 /** 1425 * Performs any necessary processing for a search request message. 1426 * 1427 * @param m The log message to be processed. 1428 */ 1429 private void processSearchRequestInternal( 1430 final SearchRequestAccessLogMessage m) 1431 { 1432 final SearchScope scope = m.getScope(); 1433 if (scope != null) 1434 { 1435 if (scope != SearchScope.BASE) 1436 { 1437 numNonBaseSearches++; 1438 } 1439 1440 AtomicLong scopeCount = searchScopes.get(scope); 1441 if (scopeCount == null) 1442 { 1443 scopeCount = new AtomicLong(0L); 1444 searchScopes.put(scope, scopeCount); 1445 } 1446 scopeCount.incrementAndGet(); 1447 1448 if (! scope.equals(SearchScope.BASE)) 1449 { 1450 final Filter filter = m.getParsedFilter(); 1451 if (filter != null) 1452 { 1453 final String genericString = new GenericFilter(filter).toString(); 1454 AtomicLong filterCount = filterTypes.get(genericString); 1455 if (filterCount == null) 1456 { 1457 filterCount = new AtomicLong(0L); 1458 filterTypes.put(genericString, filterCount); 1459 } 1460 filterCount.incrementAndGet(); 1461 } 1462 } 1463 } 1464 } 1465 1466 1467 1468 /** 1469 * Performs any necessary processing for an unbind request message. 1470 * 1471 * @param m The log message to be processed. 1472 */ 1473 private void processUnbindRequest(final UnbindRequestAccessLogMessage m) 1474 { 1475 numUnbinds++; 1476 } 1477 1478 1479 1480 /** 1481 * Performs any necessary processing for an add result message. 1482 * 1483 * @param m The log message to be processed. 1484 */ 1485 private void processAddResult(final AddResultAccessLogMessage m) 1486 { 1487 numAdds++; 1488 1489 updateResultCodeCount(m.getResultCode(), addResultCodes); 1490 addProcessingDuration += 1491 doubleValue(m.getProcessingTimeMillis(), addProcessingTimes); 1492 1493 final Boolean uncachedDataAccessed = m.getUncachedDataAccessed(); 1494 if ((uncachedDataAccessed != null) && uncachedDataAccessed) 1495 { 1496 numUncachedAdds++; 1497 } 1498 } 1499 1500 1501 1502 /** 1503 * Performs any necessary processing for a bind result message. 1504 * 1505 * @param m The log message to be processed. 1506 */ 1507 private void processBindResult(final BindResultAccessLogMessage m) 1508 { 1509 numBinds++; 1510 1511 updateResultCodeCount(m.getResultCode(), bindResultCodes); 1512 bindProcessingDuration += 1513 doubleValue(m.getProcessingTimeMillis(), bindProcessingTimes); 1514 1515 final String ccp = m.getClientConnectionPolicy(); 1516 if (ccp != null) 1517 { 1518 AtomicLong l = clientConnectionPolicies.get(ccp); 1519 if (l == null) 1520 { 1521 l = new AtomicLong(0L); 1522 clientConnectionPolicies.put(ccp, l); 1523 } 1524 l.incrementAndGet(); 1525 } 1526 1527 final Boolean uncachedDataAccessed = m.getUncachedDataAccessed(); 1528 if ((uncachedDataAccessed != null) && uncachedDataAccessed) 1529 { 1530 numUncachedBinds++; 1531 } 1532 } 1533 1534 1535 1536 /** 1537 * Performs any necessary processing for a compare result message. 1538 * 1539 * @param m The log message to be processed. 1540 */ 1541 private void processCompareResult(final CompareResultAccessLogMessage m) 1542 { 1543 numCompares++; 1544 1545 updateResultCodeCount(m.getResultCode(), compareResultCodes); 1546 compareProcessingDuration += 1547 doubleValue(m.getProcessingTimeMillis(), compareProcessingTimes); 1548 1549 final Boolean uncachedDataAccessed = m.getUncachedDataAccessed(); 1550 if ((uncachedDataAccessed != null) && uncachedDataAccessed) 1551 { 1552 numUncachedCompares++; 1553 } 1554 } 1555 1556 1557 1558 /** 1559 * Performs any necessary processing for a delete result message. 1560 * 1561 * @param m The log message to be processed. 1562 */ 1563 private void processDeleteResult(final DeleteResultAccessLogMessage m) 1564 { 1565 numDeletes++; 1566 1567 updateResultCodeCount(m.getResultCode(), deleteResultCodes); 1568 deleteProcessingDuration += 1569 doubleValue(m.getProcessingTimeMillis(), deleteProcessingTimes); 1570 1571 final Boolean uncachedDataAccessed = m.getUncachedDataAccessed(); 1572 if ((uncachedDataAccessed != null) && uncachedDataAccessed) 1573 { 1574 numUncachedDeletes++; 1575 } 1576 } 1577 1578 1579 1580 /** 1581 * Performs any necessary processing for an extended result message. 1582 * 1583 * @param m The log message to be processed. 1584 */ 1585 private void processExtendedResult(final ExtendedResultAccessLogMessage m) 1586 { 1587 numExtended++; 1588 1589 final String id = m.getConnectionID() + "-" + m.getOperationID(); 1590 if (!processedRequests.remove(id)) 1591 { 1592 processExtendedRequestInternal(m); 1593 } 1594 1595 updateResultCodeCount(m.getResultCode(), extendedResultCodes); 1596 extendedProcessingDuration += 1597 doubleValue(m.getProcessingTimeMillis(), extendedProcessingTimes); 1598 1599 final String ccp = m.getClientConnectionPolicy(); 1600 if (ccp != null) 1601 { 1602 AtomicLong l = clientConnectionPolicies.get(ccp); 1603 if (l == null) 1604 { 1605 l = new AtomicLong(0L); 1606 clientConnectionPolicies.put(ccp, l); 1607 } 1608 l.incrementAndGet(); 1609 } 1610 1611 final Boolean uncachedDataAccessed = m.getUncachedDataAccessed(); 1612 if ((uncachedDataAccessed != null) && uncachedDataAccessed) 1613 { 1614 numUncachedExtended++; 1615 } 1616 } 1617 1618 1619 1620 /** 1621 * Performs any necessary processing for a modify result message. 1622 * 1623 * @param m The log message to be processed. 1624 */ 1625 private void processModifyResult(final ModifyResultAccessLogMessage m) 1626 { 1627 numModifies++; 1628 1629 updateResultCodeCount(m.getResultCode(), modifyResultCodes); 1630 modifyProcessingDuration += 1631 doubleValue(m.getProcessingTimeMillis(), modifyProcessingTimes); 1632 1633 final Boolean uncachedDataAccessed = m.getUncachedDataAccessed(); 1634 if ((uncachedDataAccessed != null) && uncachedDataAccessed) 1635 { 1636 numUncachedModifies++; 1637 } 1638 } 1639 1640 1641 1642 /** 1643 * Performs any necessary processing for a modify DN result message. 1644 * 1645 * @param m The log message to be processed. 1646 */ 1647 private void processModifyDNResult(final ModifyDNResultAccessLogMessage m) 1648 { 1649 numModifyDNs++; 1650 1651 updateResultCodeCount(m.getResultCode(), modifyDNResultCodes); 1652 modifyDNProcessingDuration += 1653 doubleValue(m.getProcessingTimeMillis(), modifyDNProcessingTimes); 1654 1655 final Boolean uncachedDataAccessed = m.getUncachedDataAccessed(); 1656 if ((uncachedDataAccessed != null) && uncachedDataAccessed) 1657 { 1658 numUncachedModifyDNs++; 1659 } 1660 } 1661 1662 1663 1664 /** 1665 * Performs any necessary processing for a search result message. 1666 * 1667 * @param m The log message to be processed. 1668 */ 1669 private void processSearchResult(final SearchResultAccessLogMessage m) 1670 { 1671 numSearches++; 1672 1673 final String id = m.getConnectionID() + "-" + m.getOperationID(); 1674 if (!processedRequests.remove(id)) 1675 { 1676 processSearchRequestInternal(m); 1677 } 1678 1679 final ResultCode resultCode = m.getResultCode(); 1680 updateResultCodeCount(resultCode, searchResultCodes); 1681 searchProcessingDuration += 1682 doubleValue(m.getProcessingTimeMillis(), searchProcessingTimes); 1683 1684 final Long entryCount = m.getEntriesReturned(); 1685 if (entryCount != null) 1686 { 1687 AtomicLong l = searchEntryCounts.get(entryCount); 1688 if (l == null) 1689 { 1690 l = new AtomicLong(0L); 1691 searchEntryCounts.put(entryCount, l); 1692 } 1693 l.incrementAndGet(); 1694 } 1695 1696 final Boolean isUnindexed = m.isUnindexed(); 1697 if ((isUnindexed != null) && isUnindexed) 1698 { 1699 numUnindexedAttempts++; 1700 if (resultCode == ResultCode.SUCCESS) 1701 { 1702 numUnindexedSuccessful++; 1703 } 1704 else 1705 { 1706 numUnindexedFailed++; 1707 } 1708 } 1709 1710 final Boolean uncachedDataAccessed = m.getUncachedDataAccessed(); 1711 if ((uncachedDataAccessed != null) && uncachedDataAccessed) 1712 { 1713 numUncachedSearches++; 1714 } 1715 } 1716 1717 1718 1719 /** 1720 * Updates the count for the provided result code in the given map. 1721 * 1722 * @param rc The result code for which to update the count. 1723 * @param m The map used to hold counts by result code. 1724 */ 1725 private static void updateResultCodeCount(final ResultCode rc, 1726 final HashMap<ResultCode,AtomicLong> m) 1727 { 1728 if (rc == null) 1729 { 1730 return; 1731 } 1732 1733 AtomicLong l = m.get(rc); 1734 if (l == null) 1735 { 1736 l = new AtomicLong(0L); 1737 m.put(rc, l); 1738 } 1739 l.incrementAndGet(); 1740 } 1741 1742 1743 1744 /** 1745 * Retrieves the double value for the provided {@code Double} object. 1746 * 1747 * @param d The {@code Double} object for which to retrieve the value. 1748 * @param m The processing time histogram map to be updated. 1749 * 1750 * @return The double value of the provided {@code Double} object if it was 1751 * non-{@code null}, or 0.0 if it was {@code null}. 1752 */ 1753 private static double doubleValue(final Double d, 1754 final HashMap<Long,AtomicLong> m) 1755 { 1756 if (d == null) 1757 { 1758 return 0.0; 1759 } 1760 else 1761 { 1762 for (final Map.Entry<Long,AtomicLong> e : m.entrySet()) 1763 { 1764 if (d <= e.getKey()) 1765 { 1766 e.getValue().incrementAndGet(); 1767 break; 1768 } 1769 } 1770 1771 return d; 1772 } 1773 } 1774 1775 1776 1777 /** 1778 * Retrieves a list of the most frequently-occurring elements in the 1779 * provided map, paired with the number of times each value occurred. 1780 * 1781 * @param <K> The type of object used as the key for the provided map. 1782 * @param m The map to be examined. It is expected that the values of the 1783 * map will be the count of occurrences for the keys. 1784 * @param n The number of elements to return. 1785 * 1786 * @return A list of the most frequently-occurring elements in the provided 1787 * map. 1788 */ 1789 private static <K> List<ObjectPair<K,Long>> getMostCommonElements( 1790 final Map<K,AtomicLong> m, 1791 final int n) 1792 { 1793 final TreeMap<Long,List<K>> reverseMap = 1794 new TreeMap<>(new ReverseComparator<Long>()); 1795 for (final Map.Entry<K,AtomicLong> e : m.entrySet()) 1796 { 1797 final Long count = e.getValue().get(); 1798 List<K> list = reverseMap.get(count); 1799 if (list == null) 1800 { 1801 list = new ArrayList<>(n); 1802 reverseMap.put(count, list); 1803 } 1804 list.add(e.getKey()); 1805 } 1806 1807 final ArrayList<ObjectPair<K,Long>> returnList = new ArrayList<>(n); 1808 for (final Map.Entry<Long,List<K>> e : reverseMap.entrySet()) 1809 { 1810 final Long l = e.getKey(); 1811 for (final K k : e.getValue()) 1812 { 1813 returnList.add(new ObjectPair<>(k, l)); 1814 } 1815 1816 if (returnList.size() >= n) 1817 { 1818 break; 1819 } 1820 } 1821 1822 return returnList; 1823 } 1824 1825 1826 1827 /** 1828 * Writes a breakdown of the processing times for a specified type of 1829 * operation. 1830 * 1831 * @param t The name of the operation type. 1832 * @param n The total number of operations of the specified type that were 1833 * processed by the server. 1834 * @param m The map of operation counts by processing time bucket. 1835 */ 1836 private void printProcessingTimeHistogram(final String t, final long n, 1837 final LinkedHashMap<Long,AtomicLong> m) 1838 { 1839 if (n <= 0) 1840 { 1841 return; 1842 } 1843 1844 out(); 1845 out("Count of ", t, " operations by processing time:"); 1846 1847 long lowerBound = 0; 1848 long accumulatedCount = 0; 1849 final Iterator<Map.Entry<Long,AtomicLong>> i = m.entrySet().iterator(); 1850 while (i.hasNext()) 1851 { 1852 final Map.Entry<Long,AtomicLong> e = i.next(); 1853 final long upperBound = e.getKey(); 1854 final long count = e.getValue().get(); 1855 final double categoryPercent = 100.0 * count / n; 1856 1857 accumulatedCount += count; 1858 final double accumulatedPercent = 100.0 * accumulatedCount / n; 1859 1860 if (i.hasNext()) 1861 { 1862 out("Between ", lowerBound, "ms and ", upperBound, "ms: ", 1863 count, " (", decimalFormat.format(categoryPercent), "%, ", 1864 decimalFormat.format(accumulatedPercent), "% accumulated)"); 1865 lowerBound = upperBound; 1866 } 1867 else 1868 { 1869 out("Greater than ", lowerBound, "ms: ", count, " (", 1870 decimalFormat.format(categoryPercent), "%, ", 1871 decimalFormat.format(accumulatedPercent), "% accumulated)"); 1872 } 1873 } 1874 } 1875 1876 1877 1878 /** 1879 * Optionally prints information about the number and percent of operations of 1880 * the specified type that involved access to uncached data. 1881 * 1882 * @param operationType The type of operation. 1883 * @param numUncached The number of operations of the specified type that 1884 * involved access to uncached data. 1885 * @param numTotal The total number of operations of the specified 1886 * type. 1887 */ 1888 private void printUncached(final String operationType, final long numUncached, 1889 final long numTotal) 1890 { 1891 if (numUncached == 0) 1892 { 1893 return; 1894 } 1895 1896 out(operationType, ": ", numUncached, " (", 1897 decimalFormat.format(100.0 * numUncached / numTotal), "%)"); 1898 } 1899}