OPENDJ-902 (CR-1702) Add connectionID to the HTTP access log + move to exte...

Jean-Noel Rouvignac

21.47.2013 d13f4bb71bcd9e903cd87e6f2625a9f8dc1b5ed6

OPENDJ-902 (CR-1702) Add connectionID to the HTTP access log + move to extended log format
OPENDJ-858 (CR-1702) Add stats tracking to HTTP client connections



In HTTP access log, changed the name of the non standard "datetime" field to "x-datetime".
Added the "x-etime" field that outputs as a number.
Added validation for the log format that outputs error messages.


FileBasedHTTPAccessLogPublisherConfiguration.xml, FileBasedHTTPAccessLogPublisherConfiguration.properties:
Renamed the "datetime" field to "x-datetime" + added the "x-etime" field.
Improved the description of the ds-cfg-log-format.

TextHTTPAccessLogPublisher.java, config.properties:
Extracted constants for all supported field names.
Added ALL_SUPPORTED_FIELDS constant.
Changed logFormatFields instance member from String[] to List<String>.
Added validateLogFormat() which can output new error messages and called it from applyConfigurationChange() and initializeLogPublisher().
Added subtract().

HTTPClientConnection.java, HTTPRequestInfo.java:
Added instance member totalProcessingTime.
In sendResponse(), added to the totalProcessingTime + extracted method getProcessingTime().
Added getTotalProcessingTime().

 opends/src/admin/defn/org/opends/server/admin/std/FileBasedHTTPAccessLogPublisherConfiguration.xml

@@ -292,8 +292,8 @@
    </adm:synopsis>
    <adm:default-behavior>
      <adm:defined>
        <adm:value>cs-host c-ip cs-username datetime cs-method cs-uri-query 
        cs-version sc-status sc-bytes cs(User-Agent) x-connection-id</adm:value>
        <adm:value>cs-host c-ip cs-username x-datetime cs-method cs-uri-query 
        cs-version sc-status cs(User-Agent) x-connection-id x-etime</adm:value>
      </adm:defined>
    </adm:default-behavior>
    <adm:syntax>
@@ -302,15 +302,24 @@
        <adm:regex>[a-zA-Z0-9-()]+( [a-zA-Z0-9-()]+)*</adm:regex>
        <adm:usage>FORMAT</adm:usage>
          <adm:synopsis>
            A string describing the extended log format to be used for logging
            HTTP accesses. Available values are listed on the W3C working draft
            http://www.w3.org/TR/WD-logfile.html and Microsoft website
            A space separated list of fields describing the extended log format
            to be used for logging HTTP accesses. Available values are listed on
            the W3C working draft http://www.w3.org/TR/WD-logfile.html
            and Microsoft website
            http://www.microsoft.com/technet/prodtechnol/WindowsServer2003/Library/IIS/676400bc-8969-4aa7-851a-9319490a9bbb.mspx?mfr=true
            . Please note that "date" and "time" have been merged into
            "datetime" and that its ouput is controlled by 
            "ds-cfg-log-record-time-format" property. OpenDJ adds the 
            application specific field "x-connection-id" which displays the
            internal connection ID assigned to the HTTP client connection.

            OpenDJ supports the following standard fields: "c-ip", "c-port",
            "cs-host", "cs-method", "cs-uri-query", "cs(User-Agent)",
            "cs-username", "cs-version", "s-computername", "s-ip", "s-port",
            "sc-status".
            
            OpenDJ supports the following application specific field extensions:
            "x-connection-id"  displays the internal connection ID assigned to
            the HTTP client connection, "x-datetime"  displays the completion
            date and time for the logged HTTP request and its ouput is
            controlled by the "ds-cfg-log-record-time-format" property,
            "x-etime"  displays the total execution time for the logged HTTP
            request.
          </adm:synopsis>
        </adm:pattern>
      </adm:string>

 opends/src/admin/messages/FileBasedHTTPAccessLogPublisherCfgDefn.properties

@@ -13,7 +13,7 @@
property.log-file-permissions.synopsis=The UNIX permissions of the log files created by this File Based HTTP Access Log Publisher.
property.log-file-permissions.syntax.string.pattern.synopsis=A valid UNIX mode string. The mode string must contain three digits between zero and seven.
property.log-format.synopsis=Specifies how log records should be formatted and written to the HTTP access log.
property.log-format.syntax.string.pattern.synopsis=A string describing the extended log format to be used for logging HTTP accesses. Available values are listed on the W3C working draft http://www.w3.org/TR/WD-logfile.html and Microsoft website http://www.microsoft.com/technet/prodtechnol/WindowsServer2003/Library/IIS/676400bc-8969-4aa7-851a-9319490a9bbb.mspx?mfr=true . Please note that "date" and "time" have been merged into "datetime" and that its ouput is controlled by "ds-cfg-log-record-time-format" property. OpenDJ adds the application specific field "x-connection-id" which displays the internal connection ID assigned to the HTTP client connection.
property.log-format.syntax.string.pattern.synopsis=A space separated list of fields describing the extended log format to be used for logging HTTP accesses. Available values are listed on the W3C working draft http://www.w3.org/TR/WD-logfile.html and Microsoft website http://www.microsoft.com/technet/prodtechnol/WindowsServer2003/Library/IIS/676400bc-8969-4aa7-851a-9319490a9bbb.mspx?mfr=true OpenDJ supports the following standard fields: "c-ip", "c-port", "cs-host", "cs-method", "cs-uri-query", "cs(User-Agent)", "cs-username", "cs-version", "s-computername", "s-ip", "s-port", "sc-status". OpenDJ supports the following application specific field extensions: "x-connection-id" displays the internal connection ID assigned to the HTTP client connection, "x-datetime" displays the completion date and time for the logged HTTP request and its ouput is controlled by the "ds-cfg-log-record-time-format" property, "x-etime" displays the total execution time for the logged HTTP request.
property.log-record-time-format.synopsis=Specifies the format string that is used to generate log record timestamps.
property.log-record-time-format.syntax.string.pattern.synopsis=Any valid format string that can be used with the java.text.SimpleDateFormat class.
property.queue-size.synopsis=The maximum number of log records that can be stored in the asynchronous queue.

 opends/src/messages/messages/config.properties

@@ -2181,3 +2181,8 @@
SEVERE_ERR_CONFIG_LOGGER_INVALID_HTTP_ACCESS_LOGGER_CLASS_732=Class %s specified \
 in attribute ds-cfg-java-class of configuration entry %s cannot be \
 instantiated as a Directory Server HTTP access logger:  %s
SEVERE_ERR_CONFIG_LOGGING_EMPTY_LOG_FORMAT_733=The log format for configuration \
 entry %s is empty. No information will be logged even if logging is activated
MILD_WARN_CONFIG_LOGGING_UNSUPPORTED_FIELDS_IN_LOG_FORMAT_734=The log format \
 for %s contains the folowing unsupported fields: %s. Their output will be \
 replaced with a dash ("-") character

 opends/src/server/org/opends/server/loggers/HTTPRequestInfo.java

@@ -134,6 +134,13 @@
  long getConnectionID();

  /**
   * Returns the total processing time for this HTTP request.
   *
   * @return the total processing time for this HTTP request
   */
  long getTotalProcessingTime();

  /**
   * Logs the current request info in the HTTP access log.
   *
   * @param statusCode

 opends/src/server/org/opends/server/loggers/TextHTTPAccessLogPublisher.java

@@ -33,9 +33,13 @@
import java.io.IOException;
import java.text.SimpleDateFormat;
import java.util.ArrayList;
import java.util.Arrays;
import java.util.Collection;
import java.util.HashMap;
import java.util.HashSet;
import java.util.List;
import java.util.Map;
import java.util.Set;

import org.opends.messages.Message;
import org.opends.server.admin.server.ConfigurationChangeListener;
@@ -60,6 +64,30 @@
    implements ConfigurationChangeListener<FileBasedHTTPAccessLogPublisherCfg>
{

  // Extended log format standard fields
  private static final String ELF_C_IP = "c-ip";
  private static final String ELF_C_PORT = "c-port";
  private static final String ELF_CS_HOST = "cs-host";
  private static final String ELF_CS_METHOD = "cs-method";
  private static final String ELF_CS_URI_QUERY = "cs-uri-query";
  private static final String ELF_CS_USER_AGENT = "cs(User-Agent)";
  private static final String ELF_CS_USERNAME = "cs-username";
  private static final String ELF_CS_VERSION = "cs-version";
  private static final String ELF_S_COMPUTERNAME = "s-computername";
  private static final String ELF_S_IP = "s-ip";
  private static final String ELF_S_PORT = "s-port";
  private static final String ELF_SC_STATUS = "sc-status";
  // Application specific fields (eXtensions)
  private static final String X_CONNECTION_ID = "x-connection-id";
  private static final String X_DATETIME = "x-datetime";
  private static final String X_ETIME = "x-etime";

  private static final Set<String> ALL_SUPPORTED_FIELDS = new HashSet<String>(
      Arrays.asList(ELF_C_IP, ELF_C_PORT, ELF_CS_HOST, ELF_CS_METHOD,
          ELF_CS_URI_QUERY, ELF_CS_USER_AGENT, ELF_CS_USERNAME, ELF_CS_VERSION,
          ELF_S_COMPUTERNAME, ELF_S_IP, ELF_S_PORT, ELF_SC_STATUS,
          X_CONNECTION_ID, X_DATETIME, X_ETIME));

  /**
   * Returns an instance of the text HTTP access log publisher that will print
   * all messages to the provided writer. This is used to print the messages to
@@ -83,7 +111,7 @@

  private TextWriter writer = null;
  private FileBasedHTTPAccessLogPublisherCfg cfg = null;
  private String[] logFormatFields;
  private List<String> logFormatFields;
  private String timeStampFormat = "dd/MMM/yyyy:HH:mm:ss Z";


@@ -95,7 +123,7 @@
    // Default result code.
    ResultCode resultCode = ResultCode.SUCCESS;
    boolean adminActionRequired = false;
    final ArrayList<Message> messages = new ArrayList<Message>();
    final List<Message> messages = new ArrayList<Message>();

    final File logFile = getFileForPath(config.getLogFile());
    final FileNamingPolicy fnPolicy = new TimeStampNaming(logFile);
@@ -153,7 +181,7 @@
        {
          // The asynchronous setting is being turned off.
          final AsynchronousTextWriter asyncWriter =
            ((AsynchronousTextWriter) writer);
              (AsynchronousTextWriter) writer;
          writer = mfWriter;
          asyncWriter.shutdown(false);
        }
@@ -161,7 +189,7 @@
        if (writer instanceof ParallelTextWriter && !config.isAsynchronous())
        {
          // The asynchronous setting is being turned off.
          final ParallelTextWriter asyncWriter = ((ParallelTextWriter) writer);
          final ParallelTextWriter asyncWriter = (ParallelTextWriter) writer;
          writer = mfWriter;
          asyncWriter.shutdown(false);
        }
@@ -186,8 +214,8 @@
          writer = asyncWriter;
        }

        if ((cfg.isAsynchronous() && config.isAsynchronous())
            && (cfg.getQueueSize() != config.getQueueSize()))
        if (cfg.isAsynchronous() && config.isAsynchronous()
            && cfg.getQueueSize() != config.getQueueSize())
        {
          adminActionRequired = true;
        }
@@ -200,6 +228,13 @@

        cfg = config;
        logFormatFields = extractFieldsOrder(cfg.getLogFormat());
        Message errorMessage = validateLogFormat(logFormatFields);
        if (errorMessage != null)
        {
          resultCode = DirectoryServer.getServerErrorResultCode();
          adminActionRequired = true;
          messages.add(errorMessage);
        }
      }
    }
    catch (final Exception e)
@@ -214,15 +249,59 @@
  }


  private String[] extractFieldsOrder(String logFormat)
  private List<String> extractFieldsOrder(String logFormat)
  {
    if (logFormat != null)
    {
      return logFormat.split("\\s");
    // there will always be at least one field value due to the regexp
    // validating the log format
    return Arrays.asList(logFormat.split(" "));
  }

  /**
   * Validates the provided fields for the log format.
   *
   * @param fields
   *          the fields comprising the log format.
   * @return an error message when validation fails, null otherwise
   */
  private Message validateLogFormat(List<String> fields)
  {
    final Collection<String> unsupportedFields =
        subtract(fields, ALL_SUPPORTED_FIELDS);
    if (!unsupportedFields.isEmpty())
    { // there are some unsupported fields. List them.
      return WARN_CONFIG_LOGGING_UNSUPPORTED_FIELDS_IN_LOG_FORMAT.get(cfg.dn()
          .toString(), collectionToString(unsupportedFields, ", "));
    }
    if (fields.size() == unsupportedFields.size())
    { // all fields are unsupported
      return ERR_CONFIG_LOGGING_EMPTY_LOG_FORMAT.get(cfg.dn().toString());
    }
    return null;
  }

  /**
   * Returns a new Collection containing a - b.
   *
   * @param <T>
   * @param a
   *          the collection to subtract from, must not be null
   * @param b
   *          the collection to subtract, must not be null
   * @return a new collection with the results
   */
  private <T> Collection<T> subtract(Collection<T> a, Collection<T> b)
  {
    final Collection<T> result = new ArrayList<T>();
    for (T elem : a)
    {
      if (!b.contains(elem))
      {
        result.add(elem);
      }
    }
    return result;
  }

  /** {@inheritDoc} */
  @Override
  public void initializeLogPublisher(
@@ -289,11 +368,15 @@
      final Message message = ERR_CONFIG_LOGGING_CANNOT_OPEN_FILE.get(
          logFile.toString(), cfg.dn().toString(), String.valueOf(e));
      throw new InitializationException(message, e);

    }

    this.cfg = cfg;
    logFormatFields = extractFieldsOrder(cfg.getLogFormat());
    Message error = validateLogFormat(logFormatFields);
    if (error != null)
    {
      throw new InitializationException(error);
    }
    timeStampFormat = cfg.getLogRecordTimeFormat();

    cfg.addFileBasedHTTPAccessChangeListener(this);
@@ -379,25 +462,27 @@
  public void logRequestInfo(HTTPRequestInfo ri)
  {
    final Map<String, Object> fields = new HashMap<String, Object>();
    fields.put("c-ip", ri.getClientAddress());
    fields.put("cs-host", ri.getClientHost());
    fields.put("c-port", ri.getClientPort());
    fields.put("s-ip", ri.getServerAddress());
    fields.put("s-computername", ri.getServerHost());
    fields.put("s-port", ri.getServerPort());
    fields.put("cs-username", ri.getAuthUser());
    fields.put("datetime", TimeThread.getUserDefinedTime(timeStampFormat));
    fields.put("cs-method", ri.getMethod());
    fields.put("cs-uri-query", ri.getQuery());
    fields.put("cs-version", ri.getProtocol());
    fields.put("sc-status", ri.getStatusCode());
    fields.put("cs(User-Agent)", ri.getUserAgent());
    fields.put("x-connection-id", ri.getConnectionID());
    fields.put(ELF_C_IP, ri.getClientAddress());
    fields.put(ELF_C_PORT, ri.getClientPort());
    fields.put(ELF_CS_HOST, ri.getClientHost());
    fields.put(ELF_CS_METHOD, ri.getMethod());
    fields.put(ELF_CS_URI_QUERY, ri.getQuery());
    fields.put(ELF_CS_USER_AGENT, ri.getUserAgent());
    fields.put(ELF_CS_USERNAME, ri.getAuthUser());
    fields.put(ELF_CS_VERSION, ri.getProtocol());
    fields.put(ELF_S_IP, ri.getServerAddress());
    fields.put(ELF_S_COMPUTERNAME, ri.getServerHost());
    fields.put(ELF_S_PORT, ri.getServerPort());
    fields.put(ELF_SC_STATUS, ri.getStatusCode());
    fields.put(X_CONNECTION_ID, ri.getConnectionID());
    fields.put(X_DATETIME, TimeThread.getUserDefinedTime(timeStampFormat));
    fields.put(X_ETIME, ri.getTotalProcessingTime());

    writeLogRecord(fields, logFormatFields);
  }

  private void writeLogRecord(Map<String, Object> fields, String... fieldnames)
  private void writeLogRecord(Map<String, Object> fields,
      List<String> fieldnames)
  {
    if (fieldnames == null)
    {

 opends/src/server/org/opends/server/protocols/http/HTTPClientConnection.java

@@ -186,6 +186,9 @@
  private final HTTPStatistics statTracker;
  private boolean useNanoTime = false;

  /** Total execution time for this request. */
  private AtomicLong totalProcessingTime = new AtomicLong();

  /** The protocol in use for this client connection. */
  private String protocol;

@@ -298,6 +301,13 @@

  /** {@inheritDoc} */
  @Override
  public long getTotalProcessingTime()
  {
    return totalProcessingTime.get();
  }

  /** {@inheritDoc} */
  @Override
  public String getProtocol()
  {
    return protocol;
@@ -370,17 +380,11 @@
  @Override
  public void sendResponse(Operation operation)
  {
    final long time = getProcessingTime(operation);
    this.totalProcessingTime.addAndGet(time);

    if (keepStats)
    {
      long time;
      if (useNanoTime)
      {
        time = operation.getProcessingNanoTime();
      }
      else
      {
        time = operation.getProcessingTime();
      }
      this.statTracker.updateRequestMonitoringData(getMethod(), time);
      this.statTracker.updateOperationMonitoringData(operation
          .getOperationType(), time);
@@ -407,6 +411,15 @@
    }
  }

  private long getProcessingTime(Operation operation)
  {
    if (useNanoTime)
    {
      return operation.getProcessingNanoTime();
    }
    return operation.getProcessingTime();
  }

  private ProtocolOp toResponseProtocolOp(Operation operation)
  {
    final int resultCode = operation.getResultCode().getIntValue();