OPENDJ-3031: HTTP access logger does not log failed requests

Yannick Lecaillez

24.40.2016 0443d88397c7d18e516ae332db00eb1489f30184

OPENDJ-3031: HTTP access logger does not log failed requests

Move the HTTPRequestInfo logging information into a context so that
every filter in the chain can add information (i.e: authenticated user).
These information are then logged when the response is sent.

 opendj-server-legacy/src/main/java/org/opends/server/protocols/http/HTTPClientConnection.java

@@ -19,26 +19,22 @@
import static org.forgerock.opendj.adapter.server3x.Converters.getResponseResult;
import static org.forgerock.opendj.ldap.LdapException.newLdapException;
import static org.opends.messages.ProtocolMessages.WARN_CLIENT_DISCONNECT_IN_PROGRESS;
import static org.opends.server.loggers.CommonAudit.DEFAULT_TRANSACTION_ID;
import static org.opends.server.loggers.AccessLogger.logDisconnect;

import java.net.InetAddress;
import java.net.URI;
import java.net.UnknownHostException;
import java.util.ArrayList;
import java.util.Collection;
import java.util.Map;
import java.util.concurrent.ConcurrentHashMap;
import java.util.concurrent.atomic.AtomicInteger;
import java.util.concurrent.atomic.AtomicLong;

import org.forgerock.http.MutableUri;
import org.forgerock.http.header.MalformedHeaderException;
import org.forgerock.http.header.TransactionIdHeader;
import org.forgerock.http.protocol.Request;
import org.forgerock.i18n.LocalizableMessage;
import org.forgerock.i18n.LocalizableMessageBuilder;
import org.forgerock.i18n.slf4j.LocalizedLogger;
import org.forgerock.opendj.ldap.DN;
import org.forgerock.opendj.ldap.LdapException;
import org.forgerock.opendj.ldap.ResultCode;
import org.forgerock.opendj.ldap.SearchResultHandler;
@@ -58,8 +54,6 @@
import org.opends.server.core.ModifyOperation;
import org.opends.server.core.SearchOperation;
import org.opends.server.core.ServerContext;
import org.opends.server.loggers.HTTPAccessLogger;
import org.opends.server.loggers.HTTPRequestInfo;
import org.opends.server.protocols.ldap.AddResponseProtocolOp;
import org.opends.server.protocols.ldap.BindResponseProtocolOp;
import org.opends.server.protocols.ldap.CompareResponseProtocolOp;
@@ -74,7 +68,6 @@
import org.opends.server.protocols.ldap.SearchResultReferenceProtocolOp;
import org.opends.server.types.CancelRequest;
import org.opends.server.types.CancelResult;
import org.forgerock.opendj.ldap.DN;
import org.opends.server.types.DirectoryException;
import org.opends.server.types.DisconnectReason;
import org.opends.server.types.IntermediateResponse;
@@ -88,7 +81,7 @@
 * connection that will be accepted by an instance of the HTTP connection
 * handler.
 */
final class HTTPClientConnection extends ClientConnection implements HTTPRequestInfo
final class HTTPClientConnection extends ClientConnection
{

  // TODO JNR Confirm with Matt that persistent searches are inapplicable to Rest2LDAP.
@@ -197,16 +190,6 @@
  private final String method;
  /** The URI issued by the client. */
  private final MutableUri uri;
  /** The user agent used by the client. */
  private final String userAgent;

  /** The username that was used to authenticate. */
  private String authUser;
  /**
   * The HTTP status code returned to the client. Using 0 to say no status code
   * was set since it is not .
   */
  private final AtomicInteger statusCode = new AtomicInteger(0);

  /** The client (remote) address. */
  private final String clientAddress;
@@ -232,9 +215,6 @@
  /** Security-Strength Factor extracted from the request attribute. */
  private final int securityStrengthFactor;

  /** TransactionId for tracking of ForgeRock stack transactions. */
  private final String transactionId;

  /**
   * Constructs an instance of this class.
   * @param serverContext
@@ -263,7 +243,6 @@
            context.asContext(AttributesContext.class).getAttributes().get(SERVLET_SSF_CONSTANT));
    this.method = request.getMethod();
    this.protocol = request.getVersion();
    this.userAgent = clientCtx.getUserAgent();

    this.statTracker = this.connectionHandler.getStatTracker();

@@ -273,31 +252,8 @@
      this.statTracker.updateConnect();
      this.useNanoTime = DirectoryServer.getUseNanoTime();
    }
    this.transactionId = getTransactionId(serverContext, request);
    this.connectionID = DirectoryServer.newConnectionAccepted(this);
  }

  private String getTransactionId(ServerContext serverContext, Request request)
  {
    if (serverContext.getCommonAudit().shouldTrustTransactionIds())
    {
      try
      {
        TransactionIdHeader txHeader = request.getHeaders().get(TransactionIdHeader.class);
        return txHeader == null ? DEFAULT_TRANSACTION_ID :  txHeader.getTransactionId().getValue();
      }
      catch (MalformedHeaderException e)
      {
        // ignore it
      }
    }
    return DEFAULT_TRANSACTION_ID;
  }

  @Override
  public String getAuthUser()
  {
    return this.authUser;
    context.asContext(HttpLogContext.class).setConnectionID(connectionID);
  }

  @Override
@@ -313,12 +269,6 @@
  }

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

  @Override
  public String getProtocol()
  {
    return protocol;
@@ -331,12 +281,6 @@
  }

  @Override
  public String getClientHost()
  {
    return clientAddress; // Avoid reverse lookups.
  }

  @Override
  public int getClientPort()
  {
    return clientPort;
@@ -349,12 +293,6 @@
  }

  @Override
  public String getServerHost()
  {
    return serverAddress; // Avoid reverse lookups.
  }

  @Override
  public int getServerPort()
  {
    return serverPort;
@@ -373,12 +311,6 @@
  }

  @Override
  public String getTransactionId()
  {
    return transactionId;
  }

  @Override
  public boolean isSecure()
  {
    return isSecure;
@@ -392,7 +324,7 @@

    if (keepStats)
    {
      this.statTracker.updateRequestMonitoringData(getMethod(), time);
      this.statTracker.updateRequestMonitoringData(method, time);
      this.statTracker.updateOperationMonitoringData(operation.getOperationType(), time);
    }

@@ -510,12 +442,6 @@
    throw new RuntimeException("Not implemented");
  }

  @Override
  public void setAuthUser(String authUser)
  {
    this.authUser = authUser;
  }

  /**
   * {@inheritDoc}
   *
@@ -572,30 +498,6 @@
  }

  @Override
  public String getMethod()
  {
    return this.method;
  }

  @Override
  public URI getUri()
  {
    return this.uri.asURI();
  }

  @Override
  public int getStatusCode()
  {
    return this.statusCode.get();
  }

  @Override
  public String getUserAgent()
  {
    return this.userAgent;
  }

  @Override
  public Collection<Operation> getOperationsInProgress()
  {
    Collection<OperationWithPromise> values = operationsInProgress.values();
@@ -832,13 +734,4 @@
  {
    return true;
  }

  @Override
  public void log(int statusCode)
  {
    if (this.statusCode.compareAndSet(0, statusCode))
    { // This request was not logged before
      HTTPAccessLogger.logRequestInfo(this);
    }
  }
}

 opendj-server-legacy/src/main/java/org/opends/server/protocols/http/HTTPConnectionHandler.java

@@ -909,6 +909,7 @@
    {
      return Handlers.chainOf(
          serverContext.getHTTPRouter(),
          new HttpLogFilter(serverContext),
          new ExecuteInWorkerThreadFilter(),
          new AllowDenyFilter(currentConfig.getDeniedClient(), currentConfig.getAllowedClient()),
          new CommonAuditTransactionIdFilter(serverContext),

 opendj-server-legacy/src/main/java/org/opends/server/protocols/http/HttpLogContext.java

New file
@@ -0,0 +1,202 @@
/*
 * The contents of this file are subject to the terms of the Common Development and
 * Distribution License (the License). You may not use this file except in compliance with the
 * License.
 *
 * You can obtain a copy of the License at legal/CDDLv1.0.txt. See the License for the
 * specific language governing permission and limitations under the License.
 *
 * When distributing Covered Software, include this CDDL Header Notice in each file and include
 * the License file at legal/CDDLv1.0.txt. If applicable, add the following below the CDDL
 * Header, with the fields enclosed by brackets [] replaced by your own identifying
 * information: "Portions Copyright [year] [name of copyright owner]".
 *
 * Copyright 2016 ForgeRock AS.
 */
package org.opends.server.protocols.http;

import static org.opends.server.loggers.CommonAudit.DEFAULT_TRANSACTION_ID;

import java.net.URI;

import org.forgerock.http.header.MalformedHeaderException;
import org.forgerock.http.header.TransactionIdHeader;
import org.forgerock.http.protocol.Request;
import org.forgerock.services.context.AbstractContext;
import org.forgerock.services.context.ClientContext;
import org.forgerock.services.context.Context;
import org.opends.server.core.ServerContext;
import org.opends.server.loggers.HTTPAccessLogger;
import org.opends.server.loggers.HTTPRequestInfo;

/** This context contains the logging informations related to the request processing. */
public final class HttpLogContext extends AbstractContext implements HTTPRequestInfo
{
  /** The client (remote) address. */
  private final String clientAddress;
  /** The client (remote) port. */
  private final int clientPort;
  /** The server (local) address. */
  private final String serverAddress;
  /** The server (local) port. */
  private final int serverPort;
  /** The protocol in use for this client connection. */
  private final String protocol;
  /** The HTTP method/verb used for this request. */
  private final String method;
  /** The user agent used by the client. */
  private final String userAgent;
  /** TransactionId for tracking of ForgeRock stack transactions. */
  private final String transactionId;
  /** The URI issued by the client. */
  private final URI uri;

  private final long startTime;
  private long totalProcessingTime;
  private long connectionId;
  private int statusCode;
  private String authUser;

  HttpLogContext(Context parent, ServerContext serverContext, Request request)
  {
    super(parent, "Http Log Context");

    final ClientContext clientContext = parent.asContext(ClientContext.class);
    this.uri = request.getUri().asURI();
    this.serverAddress = uri.getHost();
    this.serverPort = uri.getPort();
    this.method = request.getMethod();
    this.protocol = request.getVersion();
    this.clientAddress = clientContext.getRemoteAddress();
    this.clientPort = clientContext.getRemotePort();
    this.userAgent = clientContext.getUserAgent();
    this.startTime = System.currentTimeMillis();
    this.transactionId = getTransactionId(serverContext, request);
  }

  private String getTransactionId(ServerContext serverContext, Request request)
  {
    if (serverContext.getCommonAudit().shouldTrustTransactionIds())
    {
      try
      {
        TransactionIdHeader txHeader = request.getHeaders().get(TransactionIdHeader.class);
        return txHeader == null ? DEFAULT_TRANSACTION_ID :  txHeader.getTransactionId().getValue();
      }
      catch (MalformedHeaderException e)
      {
        // ignore it
      }
    }
    return DEFAULT_TRANSACTION_ID;
  }

  void setConnectionID(long connectionID)
  {
    this.connectionId = connectionID;
  }

  @Override
  public void log(int statusCode)
  {
    this.statusCode = statusCode;
    totalProcessingTime = System.currentTimeMillis() - startTime;
    HTTPAccessLogger.logRequestInfo(this);
  }

  @Override
  public String getAuthUser()
  {
    return authUser;
  }

  @Override
  public void setAuthUser(String authUser)
  {
    this.authUser = authUser;
  }

  @Override
  public int getStatusCode()
  {
    return statusCode;
  }

  @Override
  public String getServerAddress()
  {
    return serverAddress;
  }

  @Override
  public String getServerHost()
  {
    return serverAddress;
  }

  @Override
  public int getServerPort()
  {
    return serverPort;
  }

  @Override
  public String getClientAddress()
  {
    return clientAddress;
  }

  @Override
  public String getClientHost()
  {
    return clientAddress;
  }

  @Override
  public int getClientPort()
  {
    return clientPort;
  }

  @Override
  public String getProtocol()
  {
    return protocol;
  }

  @Override
  public String getMethod()
  {
    return method;
  }

  @Override
  public URI getUri()
  {
    return uri;
  }

  @Override
  public String getUserAgent()
  {
    return userAgent;
  }

  @Override
  public long getConnectionID()
  {
    return connectionId;
  }

  @Override
  public long getTotalProcessingTime()
  {
    return totalProcessingTime;
  }

  @Override
  public String getTransactionId()
  {
    return transactionId;
  }
}

 opendj-server-legacy/src/main/java/org/opends/server/protocols/http/HttpLogFilter.java

New file
@@ -0,0 +1,78 @@
/*
 * The contents of this file are subject to the terms of the Common Development and
 * Distribution License (the License). You may not use this file except in compliance with the
 * License.
 *
 * You can obtain a copy of the License at legal/CDDLv1.0.txt. See the License for the
 * specific language governing permission and limitations under the License.
 *
 * When distributing Covered Software, include this CDDL Header Notice in each file and include
 * the License file at legal/CDDLv1.0.txt. If applicable, add the following below the CDDL
 * Header, with the fields enclosed by brackets [] replaced by your own identifying
 * information: "Portions Copyright [year] [name of copyright owner]".
 *
 * Copyright 2016 ForgeRock AS.
 */
package org.opends.server.protocols.http;

import static  org.opends.messages.ProtocolMessages.ERR_HTTP_ERROR_WHILE_PROCESSING_REQUEST;
import static org.opends.server.util.StaticUtils.stackTraceToSingleLineString;

import org.forgerock.http.Filter;
import org.forgerock.http.Handler;
import org.forgerock.http.protocol.Request;
import org.forgerock.http.protocol.Response;
import org.forgerock.i18n.slf4j.LocalizedLogger;
import org.forgerock.services.context.Context;
import org.forgerock.util.promise.ExceptionHandler;
import org.forgerock.util.promise.NeverThrowsException;
import org.forgerock.util.promise.Promise;
import org.forgerock.util.promise.ResultHandler;
import org.opends.server.core.ServerContext;

/**
 * Creates and inject a {@link HttpLogContext} containing information that'll be logged once the request has been
 * processed.
 */
final class HttpLogFilter implements Filter
{
  private static final LocalizedLogger logger = LocalizedLogger.getLoggerForThisClass();

  private final ServerContext serverContext;

  HttpLogFilter(final ServerContext serverContext)
  {
    this.serverContext = serverContext;
  }

  @Override
  public Promise<Response, NeverThrowsException> filter(Context context, final Request request, Handler next)
  {
    final HttpLogContext logContext = new HttpLogContext(context, serverContext, request);
    return next.handle(logContext, request).thenOnResultOrException(new ResultHandler<Response>()
    {
      @Override
      public void handleResult(Response result)
      {
        logContext.log(result.getStatus().getCode());
        if (result.getCause() != null)
        {
          logError(request, result.getCause());
        }
      }
    }, new ExceptionHandler<Exception>()
    {
      @Override
      public void handleException(Exception exception)
      {
        logError(request, exception);
      }
    });
  }

  private static void logError(Request request, Exception exception)
  {
    logger.error(ERR_HTTP_ERROR_WHILE_PROCESSING_REQUEST
        .get(request.getUri(), stackTraceToSingleLineString(exception)));
  }
}

 opendj-server-legacy/src/main/java/org/opends/server/protocols/http/SdkConnectionAdapter.java

@@ -23,7 +23,6 @@
import java.util.LinkedHashSet;
import java.util.concurrent.atomic.AtomicInteger;

import org.forgerock.http.protocol.Status;
import org.forgerock.i18n.slf4j.LocalizedLogger;
import org.forgerock.opendj.ldap.AbstractAsynchronousConnection;
import org.forgerock.opendj.ldap.ByteString;
@@ -279,11 +278,6 @@
    {
      this.clientConnection.disconnect(DisconnectReason.UNBIND, false, null);
    }

    // At this point, we try to log the request with OK status code.
    // If it was already logged, it will be a no op.
    this.clientConnection.log(Status.OK.getCode());

    isClosed = true;
  }


 opendj-server-legacy/src/main/java/org/opends/server/protocols/http/authz/HttpBasicAuthorizationMechanism.java

@@ -53,6 +53,7 @@
import org.forgerock.util.promise.Promise;
import org.opends.server.api.IdentityMapper;
import org.opends.server.core.ServerContext;
import org.opends.server.protocols.http.HttpLogContext;
import org.opends.server.protocols.http.LDAPContext;
import org.opends.server.types.DirectoryException;
import org.opends.server.types.Entry;
@@ -123,6 +124,7 @@
    @Override
    public Promise<SecurityContext, LdapException> authenticate(String username, String password, Context parentContext)
    {
      parentContext.asContext(HttpLogContext.class).setAuthUser(username);
      try
      {
        final Entry userEntry = getMappedIdentity(username);

 opendj-server-legacy/src/main/java/org/opends/server/protocols/http/authz/InternalProxyAuthzFilter.java

@@ -43,6 +43,7 @@
import org.forgerock.util.promise.Promises;
import org.opends.server.api.IdentityMapper;
import org.opends.server.core.DirectoryServer;
import org.opends.server.protocols.http.HttpLogContext;
import org.opends.server.protocols.http.LDAPContext;
import org.opends.server.types.DirectoryException;
import org.opends.server.types.Entry;
@@ -68,6 +69,7 @@
  public final Promise<Response, NeverThrowsException> filter(Context context, Request request, Handler next)
  {
    final SecurityContext securityContext = context.asContext(SecurityContext.class);
    context.asContext(HttpLogContext.class).setAuthUser(securityContext.getAuthenticationId());
    final LDAPContext ldapContext = context.asContext(LDAPContext.class);
    Connection tmp = null;
    try

 opendj-server-legacy/src/messages/org/opends/messages/protocol.properties

@@ -854,3 +854,5 @@
ERR_SNMP_CONNHANDLER_OPENDMK_JARFILES_NOT_OPERATIONAL_1507=The required \
 classes could not be loaded using jar file '%s'. Verify that the jar file \
 is not corrupted
ERR_HTTP_ERROR_WHILE_PROCESSING_REQUEST_1508=An error occurred while processing the request \
 %s: %s