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