OPENDJ-655 (CR-1309) Message about authentication failures should contain i...

Jean-Noel Rouvignac

22.59.2013 becdec4d25ac5284ffadee2a1178d1794247f921

OPENDJ-655 (CR-1309) Message about authentication failures should contain identification of the user for easier analysis. 

Refactoring of TextAccessLogPublisher prior to applying the real fix.

Extracted methods appendLabel(), appendLabelIfNotNull(), appendMessage() and appendEtime().
In logAbandonResult(), the code was not using Operation.getProcessingNanoTime() which looked like a mistake.

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

@@ -23,15 +23,14 @@
 *
 *
 *      Copyright 2006-2009 Sun Microsystems, Inc.
 *      Portions Copyright 2011-2012 ForgeRock AS
 *      Portions Copyright 2011-2013 ForgeRock AS
 */
package org.opends.server.loggers;



import static org.opends.messages.ConfigMessages.*;
import static org.opends.server.util.StaticUtils.getFileForPath;
import static org.opends.server.util.StaticUtils.stackTraceToSingleLineString;
import static org.opends.server.util.StaticUtils.*;

import java.io.File;
import java.io.IOException;
@@ -431,18 +430,11 @@
    }
    buffer.append(" result=");
    buffer.append(abandonOperation.getResultCode().getIntValue());
    final MessageBuilder msg = abandonOperation.getErrorMessage();
    if ((msg != null) && (msg.length() > 0))
    {
      buffer.append(" message=\"");
      buffer.append(msg);
      buffer.append('\"');
    }
    appendMessage(buffer, abandonOperation);

    logAdditionalLogItems(abandonOperation, buffer);

    buffer.append(" etime=");
    buffer.append(abandonOperation.getProcessingTime());
    appendEtime(buffer, abandonOperation);

    writer.writeRecord(buffer.toString());
  }
@@ -498,31 +490,14 @@
    buffer.append(" result=");
    buffer.append(addOperation.getResultCode().getIntValue());

    final MessageBuilder msg = addOperation.getErrorMessage();
    if ((msg != null) && (msg.length() > 0))
    {
      buffer.append(" message=\"");
      buffer.append(msg);
      buffer.append('\"');
    }
    appendMessage(buffer, addOperation);

    logAdditionalLogItems(addOperation, buffer);

    final DN proxiedAuthDN = addOperation.getProxiedAuthorizationDN();
    if (proxiedAuthDN != null)
    {
      buffer.append(" authzDN=\"");
      proxiedAuthDN.toString(buffer);
      buffer.append('\"');
    }
    appendLabelIfNotNull(buffer, "authzDN", addOperation
        .getProxiedAuthorizationDN());

    buffer.append(" etime=");
    long etime = addOperation.getProcessingNanoTime();
    if (etime <= -1)
    {
      etime = addOperation.getProcessingTime();
    }
    buffer.append(etime);
    appendEtime(buffer, addOperation);

    writer.writeRecord(buffer.toString());
  }
@@ -578,22 +553,15 @@
    buffer.append(" result=");
    buffer.append(bindOperation.getResultCode().getIntValue());

    final MessageBuilder msg = bindOperation.getErrorMessage();
    if ((msg != null) && (msg.length() > 0))
    {
      buffer.append(" message=\"");
      buffer.append(msg);
      buffer.append('\"');
    }
    appendMessage(buffer, bindOperation);

    final Message failureMessage = bindOperation.getAuthFailureReason();
    if (failureMessage != null)
    {
      buffer.append(" authFailureID=");
      buffer.append(failureMessage.getDescriptor().getId());
      buffer.append(" authFailureReason=\"");
      buffer.append(failureMessage);
      buffer.append('\"');
      buffer.append(" ");
      appendLabel(buffer, "authFailureReason", failureMessage);
    }

    logAdditionalLogItems(bindOperation, buffer);
@@ -606,19 +574,12 @@
        final DN authDN = authInfo.getAuthenticationDN();
        if (authDN != null)
        {
          buffer.append(" authDN=\"");
          authDN.toString(buffer);
          buffer.append('\"');
          appendLabel(buffer, "authDN", authDN);

          final DN authzDN = authInfo.getAuthorizationDN();
          if (!authDN.equals(authzDN))
          {
            buffer.append(" authzDN=\"");
            if (authzDN != null)
            {
              authzDN.toString(buffer);
            }
            buffer.append('\"');
            appendLabel(buffer, "authzDN", authzDN);
          }
        }
        else
@@ -628,13 +589,7 @@
      }
    }

    buffer.append(" etime=");
    long etime = bindOperation.getProcessingNanoTime();
    if (etime <= -1)
    {
      etime = bindOperation.getProcessingTime();
    }
    buffer.append(etime);
    appendEtime(buffer, bindOperation);

    writer.writeRecord(buffer.toString());
  }
@@ -690,31 +645,14 @@
    buffer.append(" result=");
    buffer.append(compareOperation.getResultCode().getIntValue());

    final MessageBuilder msg = compareOperation.getErrorMessage();
    if ((msg != null) && (msg.length() > 0))
    {
      buffer.append(" message=\"");
      buffer.append(msg);
      buffer.append('\"');
    }
    appendMessage(buffer, compareOperation);

    logAdditionalLogItems(compareOperation, buffer);

    final DN proxiedAuthDN = compareOperation.getProxiedAuthorizationDN();
    if (proxiedAuthDN != null)
    {
      buffer.append(" authzDN=\"");
      proxiedAuthDN.toString(buffer);
      buffer.append('\"');
    }
    appendLabelIfNotNull(buffer, "authzDN", compareOperation
        .getProxiedAuthorizationDN());

    buffer.append(" etime=");
    long etime = compareOperation.getProcessingNanoTime();
    if (etime <= -1)
    {
      etime = compareOperation.getProcessingTime();
    }
    buffer.append(etime);
    appendEtime(buffer, compareOperation);

    writer.writeRecord(buffer.toString());
  }
@@ -806,31 +744,14 @@
    buffer.append(" result=");
    buffer.append(deleteOperation.getResultCode().getIntValue());

    final MessageBuilder msg = deleteOperation.getErrorMessage();
    if ((msg != null) && (msg.length() > 0))
    {
      buffer.append(" message=\"");
      buffer.append(msg);
      buffer.append('\"');
    }
    appendMessage(buffer, deleteOperation);

    logAdditionalLogItems(deleteOperation, buffer);

    final DN proxiedAuthDN = deleteOperation.getProxiedAuthorizationDN();
    if (proxiedAuthDN != null)
    {
      buffer.append(" authzDN=\"");
      proxiedAuthDN.toString(buffer);
      buffer.append('\"');
    }
    appendLabelIfNotNull(buffer, "authzDN", deleteOperation
        .getProxiedAuthorizationDN());

    buffer.append(" etime=");
    long etime = deleteOperation.getProcessingNanoTime();
    if (etime <= -1)
    {
      etime = deleteOperation.getProcessingTime();
    }
    buffer.append(etime);
    appendEtime(buffer, deleteOperation);

    writer.writeRecord(buffer.toString());
  }
@@ -865,16 +786,9 @@
    buffer.append("]");
    buffer.append(" DISCONNECT conn=");
    buffer.append(connectionID);
    buffer.append(" reason=\"");
    buffer.append(disconnectReason);

    if (message != null)
    {
      buffer.append("\" msg=\"");
      buffer.append(message);
    }

    buffer.append("\"");
    buffer.append(" ");
    appendLabel(buffer, "reason", disconnectReason);
    appendLabelIfNotNull(buffer, "msg", message);

    writer.writeRecord(buffer.toString());
  }
@@ -936,38 +850,19 @@
      if (extOpHandler != null)
      {
        String name = extOpHandler.getExtendedOperationName();
        if (name != null)
        {
          buffer.append(" name=\"");
          buffer.append(name);
          buffer.append("\"");
        appendLabelIfNotNull(buffer, "name", name);
        }
      }
      buffer.append(" oid=\"");
      buffer.append(oid);
      buffer.append('\"');
      appendLabel(buffer, "oid", oid);
    }

    buffer.append(" result=");
    buffer.append(extendedOperation.getResultCode().getIntValue());

    final MessageBuilder msg = extendedOperation.getErrorMessage();
    if ((msg != null) && (msg.length() > 0))
    {
      buffer.append(" message=\"");
      buffer.append(msg);
      buffer.append('\"');
    }
    appendMessage(buffer, extendedOperation);

    logAdditionalLogItems(extendedOperation, buffer);

    buffer.append(" etime=");
    long etime = extendedOperation.getProcessingNanoTime();
    if (etime <= -1)
    {
      etime = extendedOperation.getProcessingTime();
    }
    buffer.append(etime);
    appendEtime(buffer, extendedOperation);

    writer.writeRecord(buffer.toString());
  }
@@ -1023,31 +918,14 @@
    buffer.append(" result=");
    buffer.append(modifyDNOperation.getResultCode().getIntValue());

    final MessageBuilder msg = modifyDNOperation.getErrorMessage();
    if ((msg != null) && (msg.length() > 0))
    {
      buffer.append(" message=\"");
      buffer.append(msg);
      buffer.append('\"');
    }
    appendMessage(buffer, modifyDNOperation);

    logAdditionalLogItems(modifyDNOperation, buffer);

    final DN proxiedAuthDN = modifyDNOperation.getProxiedAuthorizationDN();
    if (proxiedAuthDN != null)
    {
      buffer.append(" authzDN=\"");
      proxiedAuthDN.toString(buffer);
      buffer.append('\"');
    }
    appendLabelIfNotNull(buffer, "authzDN", modifyDNOperation
        .getProxiedAuthorizationDN());

    buffer.append(" etime=");
    long etime = modifyDNOperation.getProcessingNanoTime();
    if (etime <= -1)
    {
      etime = modifyDNOperation.getProcessingTime();
    }
    buffer.append(etime);
    appendEtime(buffer, modifyDNOperation);

    writer.writeRecord(buffer.toString());
  }
@@ -1103,31 +981,14 @@
    buffer.append(" result=");
    buffer.append(modifyOperation.getResultCode().getIntValue());

    final MessageBuilder msg = modifyOperation.getErrorMessage();
    if ((msg != null) && (msg.length() > 0))
    {
      buffer.append(" message=\"");
      buffer.append(msg);
      buffer.append('\"');
    }
    appendMessage(buffer, modifyOperation);

    logAdditionalLogItems(modifyOperation, buffer);

    final DN proxiedAuthDN = modifyOperation.getProxiedAuthorizationDN();
    if (proxiedAuthDN != null)
    {
      buffer.append(" authzDN=\"");
      proxiedAuthDN.toString(buffer);
      buffer.append('\"');
    }
    appendLabelIfNotNull(buffer, "authzDN", modifyOperation
        .getProxiedAuthorizationDN());

    buffer.append(" etime=");
    long etime = modifyOperation.getProcessingNanoTime();
    if (etime <= -1)
    {
      etime = modifyOperation.getProcessingTime();
    }
    buffer.append(etime);
    appendEtime(buffer, modifyOperation);

    writer.writeRecord(buffer.toString());
  }
@@ -1183,34 +1044,17 @@
    buffer.append(" result=");
    buffer.append(searchOperation.getResultCode().getIntValue());

    final MessageBuilder msg = searchOperation.getErrorMessage();
    if ((msg != null) && (msg.length() > 0))
    {
      buffer.append(" message=\"");
      buffer.append(msg);
      buffer.append('\"');
    }
    appendMessage(buffer, searchOperation);

    buffer.append(" nentries=");
    buffer.append(searchOperation.getEntriesSent());

    logAdditionalLogItems(searchOperation, buffer);

    final DN proxiedAuthDN = searchOperation.getProxiedAuthorizationDN();
    if (proxiedAuthDN != null)
    {
      buffer.append(" authzDN=\"");
      proxiedAuthDN.toString(buffer);
      buffer.append('\"');
    }
    appendLabelIfNotNull(buffer, "authzDN", searchOperation
        .getProxiedAuthorizationDN());

    buffer.append(" etime=");
    long etime = searchOperation.getProcessingNanoTime();
    if (etime <= -1)
    {
      etime = searchOperation.getProcessingTime();
    }
    buffer.append(etime);
    appendEtime(buffer, searchOperation);

    writer.writeRecord(buffer.toString());
  }
@@ -1278,9 +1122,7 @@
  private void appendAddRequest(final AddOperation addOperation,
      final StringBuilder buffer)
  {
    buffer.append(" dn=\"");
    buffer.append(addOperation.getRawEntryDN().toString());
    buffer.append("\"");
    appendLabel(buffer, "dn", addOperation.getRawEntryDN());
    appendRequestControls(addOperation, buffer);
    if (addOperation.isSynchronizationOperation())
    {
@@ -1315,9 +1157,7 @@
      break;
    }

    buffer.append(" dn=\"");
    buffer.append(bindOperation.getRawBindDN().toString());
    buffer.append("\"");
    appendLabel(buffer, "dn", bindOperation.getRawBindDN());
    appendRequestControls(bindOperation, buffer);
    if (bindOperation.isSynchronizationOperation())
    {
@@ -1330,9 +1170,8 @@
  private void appendCompareRequest(final CompareOperation compareOperation,
      final StringBuilder buffer)
  {
    buffer.append(" dn=\"");
    buffer.append(compareOperation.getRawEntryDN().toString());
    buffer.append("\" attr=");
    appendLabel(buffer, "dn", compareOperation.getRawEntryDN());
    buffer.append(" attr=");
    buffer.append(compareOperation.getAttributeType().getNameOrOID());
    appendRequestControls(compareOperation, buffer);
    if (compareOperation.isSynchronizationOperation())
@@ -1346,9 +1185,7 @@
  private void appendDeleteRequest(final DeleteOperation deleteOperation,
      final StringBuilder buffer)
  {
    buffer.append(" dn=\"");
    buffer.append(deleteOperation.getRawEntryDN().toString());
    buffer.append("\"");
    appendLabel(buffer, "dn", deleteOperation.getRawEntryDN());
    appendRequestControls(deleteOperation, buffer);
    if (deleteOperation.isSynchronizationOperation())
    {
@@ -1367,16 +1204,9 @@
    if (extOpHandler != null)
    {
      final String name = extOpHandler.getExtendedOperationName();
      if (name != null)
      {
        buffer.append(" name=\"");
        buffer.append(name);
        buffer.append("\"");
      appendLabelIfNotNull(buffer, "name", name);
      }
    }
    buffer.append(" oid=\"");
    buffer.append(oid);
    buffer.append("\"");
    appendLabel(buffer, "oid", oid);
    appendRequestControls(extendedOperation, buffer);
    if (extendedOperation.isSynchronizationOperation())
    {
@@ -1386,7 +1216,53 @@



  // Appends the common log header information to the provided buffer.
  private void appendLabel(final StringBuilder buffer, final String label,
      final Object obj)
  {
    buffer.append(" ").append(label).append("=\"");
    if (obj != null)
    {
      buffer.append(obj);
    }
    buffer.append('\"');
  }

  private void appendLabelIfNotNull(final StringBuilder buffer,
      final String label, final Object obj)
  {
    if (obj != null)
    {
      appendLabel(buffer, label, obj);
    }
  }

  private void appendMessage(final StringBuilder buffer,
      final Operation operation)
  {
    final MessageBuilder msg = operation.getErrorMessage();
    if ((msg != null) && (msg.length() > 0))
    {
      appendLabel(buffer, "message", msg);
    }
  }

  private void appendEtime(final StringBuilder buffer,
      final Operation operation)
  {
    buffer.append(" etime=");
    // the server can be configured to log processing time as nanos xor millis
    long etime = operation.getProcessingNanoTime();
    if (etime <= -1)
    {
      // if it is not configured for nanos, then use millis.
      etime = operation.getProcessingTime();
    }
    buffer.append(etime);
  }

  /**
   * Appends the common log header information to the provided buffer.
   */
  private void appendHeader(final Operation operation, final String opType,
      final String category, final StringBuilder buffer)
  {
@@ -1412,20 +1288,12 @@
  private void appendModifyDNRequest(final ModifyDNOperation modifyDNOperation,
      final StringBuilder buffer)
  {
    buffer.append(" dn=\"");
    buffer.append(modifyDNOperation.getRawEntryDN().toString());
    buffer.append("\" newRDN=\"");
    buffer.append(modifyDNOperation.getRawNewRDN().toString());
    buffer.append("\" deleteOldRDN=");
    buffer.append(modifyDNOperation.deleteOldRDN());
    appendLabel(buffer, "dn", modifyDNOperation.getRawEntryDN());
    appendLabel(buffer, "newRDN", modifyDNOperation.getRawNewRDN());
    appendLabel(buffer, "deleteOldRDN", modifyDNOperation.deleteOldRDN());

    final ByteString newSuperior = modifyDNOperation.getRawNewSuperior();
    if (newSuperior != null)
    {
      buffer.append(" newSuperior=\"");
      buffer.append(newSuperior.toString());
      buffer.append("\"");
    }
    appendLabelIfNotNull(buffer, "newSuperior", newSuperior);
    appendRequestControls(modifyDNOperation, buffer);
    if (modifyDNOperation.isSynchronizationOperation())
    {
@@ -1438,9 +1306,7 @@
  private void appendModifyRequest(final ModifyOperation modifyOperation,
      final StringBuilder buffer)
  {
    buffer.append(" dn=\"");
    buffer.append(modifyOperation.getRawEntryDN().toString());
    buffer.append("\"");
    appendLabel(buffer, "dn", modifyOperation.getRawEntryDN());
    appendRequestControls(modifyOperation, buffer);
    if (modifyOperation.isSynchronizationOperation())
    {
@@ -1495,9 +1361,8 @@
  private void appendSearchRequest(final SearchOperation searchOperation,
      final StringBuilder buffer)
  {
    buffer.append(" base=\"");
    buffer.append(searchOperation.getRawBaseDN().toString());
    buffer.append("\" scope=");
    appendLabel(buffer, "base", searchOperation.getRawBaseDN());
    buffer.append(" scope=");
    buffer.append(searchOperation.getScope());
    buffer.append(" filter=\"");
    searchOperation.getRawFilter().toString(buffer);
@@ -1530,7 +1395,9 @@



  // Appends additional log items to the provided builder.
  /**
   * Appends additional log items to the provided builder.
   */
  private void logAdditionalLogItems(final Operation operation,
      final StringBuilder builder)
  {