ToolToParseNdstraceLogs/ldapoptime.pl#

Reads specified log file to organize threads to determine start/end time of a given operation, and calculate elapsed time. Provides various operation counts. Also breaks down and translates LDAP result codes into descriptive messages. Finally, logs operations that are deemed "interesting" -- defined as:

• operations that take > 1 second
• LDAP result codes that are "abnormal" (normal = 0 5 6 49 65)
• search operations results >= 50
• all operations if -a parameter is specified

Requires#

• HTTP::Date
  Assumes that package HTTP/Date.pm is installed or in execution directory
• Intended for use on logs from eDirectory 8.7.3.1+
• Tested to run on Solaris, Linux, and Win32
• Input ndstrace log expects ndstrace filters BASE, TAGS, TIME, and LDAP to be set.
• On the LDAP Server object, Screen Options, all options except "Packet Decode" should be enabled. (Including "Additional connection and operation debugging information on all available messages".)

Here is a sample of of an operation that can be parsed:

14890 LDAP: [2005/06/27 19:15:08.764] (155.180.164.107:56534)(0x0925:0x63) Search request:
	base: "uid=MOLLY,ou=People,dc=willeke,dc=com"
	scope:0  dereference:0  sizelimit:0  timelimit:10  attrsonly:0
	filter: "(Sn=*)"
	attribute: "Sn"

What problem does this attempt to address?#

eDirectory provides a wealth of logging features, but as it seems with most complex systems, the log files that are generated are either too much or too little. Logs from ndstrace with the LDAP filters turned on provide a wealth of information. When analyzed, one can understand much more about the nature of the load that an eDirectory server is under.

If logging is turned up enough to be useful, generally it is very difficult to find what you are looking for. Even worse if you don't know exactly what you are looking for. Any reasonably busy LDAP server processes many requests that are "normal" and completely uninteresting for analysis purposes.

This script attempts to parse the logs into a form suitable for analysis.

Input#

• Win32
  specified ndstrace.log file
• UNIX
  start an ndstrace pipe to read real-time, or specified ndstrace.log file (see NOTE below)

Output#

• Summary to screen (refreshes every $refresh seconds)
• Win32 or UNIX with an input file
  • Summary to file <inputfile>.summary.txt (overwrite existing)
  • Logged operations to file <inputfile>.csv (overwrite existing)
  • Debug info to file <inputfile>.debug.txt (overwrite existing)
• UNIX (live)
  • Summary to file /var/nds/ldapsummary.log (overwrite existing)
  • Logged operations to file /var/nds/ldapmonitor.log (append to existing)
  • Debug info to file /var/nds/ldapdebug.log (overwrite existing)

Usage#

Open a command line in the directory containing the ndstrace log file to be parsed.

Usage: ldapoptime.pl options

-a Outputs all operations (usually logs only those deemed interesting)
-s Silent mode (will not print results to screen)
-f Read ndstrace log from a file

NOTE: Running on a UNIX server in "live" mode (no -f parameter specfied) works. However, the input stream from ndstrace is corrupted, and can cause unpredictable/incorrect results. Until this problem is corrected (probably a future Novell ndstrace release), the script is best used with the -f parameter.

Example execution#

     Operation:  Count:<=0.010:<=0.250:<=1.000:<=2.000: >2.000: logged:dropped
         Total: 453014: 428038:  15740:   4170:   1405:   3660:      0:      0
      DoModify:  11359:     14:   5802:   3498:   1088:    957:   2045:      0
        DoBind:  13780:  12068:   1468:     88:     55:    101:    156:      0
     DoCompare:    650:    564:     85:      1:      0:      0:      0:      0
DoTLSHandshake:   2462:    740:    551:     73:      7:   1091:   1098:      0
    DoExtended:     60:     10:     49:      1:      0:      0:      0:      0
      DoUnbind:   2334:   1782:    362:     29:     27:    134:    601:      0
     DoAbandon:    438:    438:      0:      0:      0:      0:      0:      0
       unknown:   7324:    941:    870:    256:    227:   1368:   2200:      0
      DoSearch: 418267: 411481:   6553:    223:      1:      9:    467:      1
      DoDelete:      1:      0:      0:      1:      0:      0:      0:      0

      2 : Search Operations >= 50 results

      6 : Operations Active

 441943 : LDAP Code  0 (SUCCESS)
   1777 : LDAP Code  1 (OPERATIONS ERROR)
     29 : LDAP Code  2 (PROTOCOL ERROR)
    426 : LDAP Code  3 (TIMELIMIT EXCEEDED)
    325 : LDAP Code  6 (COMPARE TRUE)
     26 : LDAP Code 32 (NO SUCH OBJECT)
   1046 : LDAP Code 49 (INVALID CREDENTIALS)
      9 : LDAP Code 52 (UNAVAILABLE)
    325 : LDAP Code 65 (OBJECT CLASS VIOLATION)
      2 : LDAP Code 80 (OTHER)

Current time: 2005-06-28 00:33:33 (local time)
Log started:  2005-06-27 18:26:44
Log end:      2005-06-27 20:04:15

Credits#

Includes "borrowed" code from LDAP Error Count.

--JGJ

More Information#

There might be more information for this subject on one of the following:

• EdirectoryAutomationScripts
• LDAP Tools From Others