From 0443d88397c7d18e516ae332db00eb1489f30184 Mon Sep 17 00:00:00 2001
From: Yannick Lecaillez <yannick.lecaillez@forgerock.com>
Date: Fri, 03 Jun 2016 14:09:09 +0000
Subject: [PATCH] OPENDJ-3031: HTTP access logger does not log failed requests

---
 opendj-server-legacy/src/main/java/org/opends/server/protocols/http/authz/HttpBasicAuthorizationMechanism.java |    2 
 opendj-server-legacy/src/main/java/org/opends/server/protocols/http/HTTPClientConnection.java                  |  115 ---------------
 opendj-server-legacy/src/main/java/org/opends/server/protocols/http/HttpLogFilter.java                         |   78 +++++++++++
 opendj-server-legacy/src/main/java/org/opends/server/protocols/http/authz/InternalProxyAuthzFilter.java        |    2 
 opendj-server-legacy/src/main/java/org/opends/server/protocols/http/SdkConnectionAdapter.java                  |    6 
 opendj-server-legacy/src/messages/org/opends/messages/protocol.properties                                      |    2 
 opendj-server-legacy/src/main/java/org/opends/server/protocols/http/HttpLogContext.java                        |  202 ++++++++++++++++++++++++++++
 opendj-server-legacy/src/main/java/org/opends/server/protocols/http/HTTPConnectionHandler.java                 |    1 
 8 files changed, 291 insertions(+), 117 deletions(-)

diff --git a/opendj-server-legacy/src/main/java/org/opends/server/protocols/http/HTTPClientConnection.java b/opendj-server-legacy/src/main/java/org/opends/server/protocols/http/HTTPClientConnection.java
index a5c5cef..fdd2482 100644
--- a/opendj-server-legacy/src/main/java/org/opends/server/protocols/http/HTTPClientConnection.java
+++ b/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);
-    }
-  }
 }
diff --git a/opendj-server-legacy/src/main/java/org/opends/server/protocols/http/HTTPConnectionHandler.java b/opendj-server-legacy/src/main/java/org/opends/server/protocols/http/HTTPConnectionHandler.java
index 1f44bdb..9c86800 100644
--- a/opendj-server-legacy/src/main/java/org/opends/server/protocols/http/HTTPConnectionHandler.java
+++ b/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),
diff --git a/opendj-server-legacy/src/main/java/org/opends/server/protocols/http/HttpLogContext.java b/opendj-server-legacy/src/main/java/org/opends/server/protocols/http/HttpLogContext.java
new file mode 100644
index 0000000..82abc2e
--- /dev/null
+++ b/opendj-server-legacy/src/main/java/org/opends/server/protocols/http/HttpLogContext.java
@@ -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;
+  }
+}
\ No newline at end of file
diff --git a/opendj-server-legacy/src/main/java/org/opends/server/protocols/http/HttpLogFilter.java b/opendj-server-legacy/src/main/java/org/opends/server/protocols/http/HttpLogFilter.java
new file mode 100644
index 0000000..9afc654
--- /dev/null
+++ b/opendj-server-legacy/src/main/java/org/opends/server/protocols/http/HttpLogFilter.java
@@ -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)));
+  }
+}
diff --git a/opendj-server-legacy/src/main/java/org/opends/server/protocols/http/SdkConnectionAdapter.java b/opendj-server-legacy/src/main/java/org/opends/server/protocols/http/SdkConnectionAdapter.java
index e73b185..a6a4d66 100644
--- a/opendj-server-legacy/src/main/java/org/opends/server/protocols/http/SdkConnectionAdapter.java
+++ b/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;
   }
 
diff --git a/opendj-server-legacy/src/main/java/org/opends/server/protocols/http/authz/HttpBasicAuthorizationMechanism.java b/opendj-server-legacy/src/main/java/org/opends/server/protocols/http/authz/HttpBasicAuthorizationMechanism.java
index 025fdd0..d1ddc7a 100644
--- a/opendj-server-legacy/src/main/java/org/opends/server/protocols/http/authz/HttpBasicAuthorizationMechanism.java
+++ b/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);
diff --git a/opendj-server-legacy/src/main/java/org/opends/server/protocols/http/authz/InternalProxyAuthzFilter.java b/opendj-server-legacy/src/main/java/org/opends/server/protocols/http/authz/InternalProxyAuthzFilter.java
index 4437bcf..7776aad 100644
--- a/opendj-server-legacy/src/main/java/org/opends/server/protocols/http/authz/InternalProxyAuthzFilter.java
+++ b/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
diff --git a/opendj-server-legacy/src/messages/org/opends/messages/protocol.properties b/opendj-server-legacy/src/messages/org/opends/messages/protocol.properties
index fdc6f98..bc92b6b 100644
--- a/opendj-server-legacy/src/messages/org/opends/messages/protocol.properties
+++ b/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

--
Gitblit v1.10.0