OPENDJ-2955 Add logs to rest2ldap gateway

Gaetan Boismal

03.49.2016 3b15a98cb11aa68f681fa7ba0dd793cb56ba02d9

OPENDJ-2955 Add logs to rest2ldap gateway

Logs internal server error response as error using a CHF Filter.
Split the HttpLogFilter in two parts:
    * One HttpAccessLogFilter which only logs response status in the http access log.
    * One ErrorLoggerFilter moved in opendj-rest2ldap module which performs internal server error logs.
      This filter also catch and logs runtime exceptions and then convert them in an internal server error response.
Also adds trace logs of Ldap requests and responses performed by rest2ldap.
For tomcat support, provides a logging.properties file in the servlet module in order to isolate rest2ldap logs out of the box (logs will go in ${catalina.base}/logs/rest2ldap.yyyy-MM-dd.log file)
This file does not alter Jetty logs. By default with Jetty, rest2ldap logs will be mixed with other logs (OOTB they are display in the console).

 opendj-rest2ldap-servlet/pom.xml

@@ -37,6 +37,11 @@

  <dependencies>
    <dependency>
      <groupId>org.slf4j</groupId>
      <artifactId>slf4j-jdk14</artifactId>
    </dependency>

    <dependency>
      <groupId>org.forgerock.http</groupId>
      <artifactId>chf-http-servlet</artifactId>
    </dependency>

 opendj-rest2ldap-servlet/src/main/webapp/WEB-INF/classes/logging.properties

New file
@@ -0,0 +1,13 @@
################################################################################################################
# Tomcat rest2ldap log file handler configuration
# By default: all rest2ldap logs will end up in ${catalina.base}/logs/rest2ldap.yyyy-MM-dd.log
# Set the log level to FINEST to enable ldap requests logging.
# See https://tomcat.apache.org/tomcat-8.0-doc/logging.html for more details about how to configure tomcat logs.
################################################################################################################
handlers = 5rest2ldap.org.apache.juli.FileHandler

5rest2ldap.org.apache.juli.FileHandler.directory = ${catalina.base}/logs
5rest2ldap.org.apache.juli.FileHandler.prefix = rest2ldap.

org.forgerock.opendj.rest2ldap.level = ERROR
org.forgerock.opendj.rest2ldap.handlers = 5rest2ldap.org.apache.juli.FileHandler

 opendj-rest2ldap/src/main/java/org/forgerock/opendj/rest2ldap/ErrorLoggerFilter.java

New file
@@ -0,0 +1,69 @@
/*
 * 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.forgerock.opendj.rest2ldap;

import static org.forgerock.http.protocol.Responses.newInternalServerError;
import static org.forgerock.opendj.rest2ldap.Rest2ldapMessages.ERR_ERROR_RESPONSE;
import static org.forgerock.opendj.rest2ldap.Rest2ldapMessages.ERR_RUNTIME_EXCEPTION;

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.http.protocol.Status;
import org.forgerock.i18n.slf4j.LocalizedLogger;
import org.forgerock.services.context.Context;
import org.forgerock.util.Function;
import org.forgerock.util.promise.NeverThrowsException;
import org.forgerock.util.promise.Promise;
import org.forgerock.util.promise.ResultHandler;

/** Logs internal server errors and runtime exceptions once the request has been processed. */
public final class ErrorLoggerFilter implements Filter {

    private static final LocalizedLogger logger = LocalizedLogger.getLoggerForThisClass();

    @Override
    public Promise<Response, NeverThrowsException> filter(final Context context,
                                                          final Request request,
                                                          final Handler next) {
        return next.handle(context, request)
                .thenOnResult(new ResultHandler<Response>() {
                    @Override
                    public void handleResult(final Response response) {
                        final Exception cause = response.getCause();
                        final Status status = response.getStatus();
                        if (status.isServerError() && cause != null) {
                            logger.error(ERR_ERROR_RESPONSE,
                                         toLog(request),
                                         status.toString(),
                                         cause.getLocalizedMessage(),
                                         cause);
                        }
                    }
                }).thenCatchRuntimeException(new Function<RuntimeException, Response, NeverThrowsException>() {
                    @Override
                    public Response apply(final RuntimeException e) {
                        logger.error(ERR_RUNTIME_EXCEPTION, toLog(request), e.getLocalizedMessage(), e);
                        return newInternalServerError(e);
                    }
                });
    }

    private String toLog(final Request request) {
        return request.getMethod() + request.getUri();
    }
}

 opendj-rest2ldap/src/main/java/org/forgerock/opendj/rest2ldap/LDAPCollectionResourceProvider.java

@@ -15,6 +15,7 @@
 */
package org.forgerock.opendj.rest2ldap;

import static org.forgerock.i18n.LocalizableMessage.raw;
import static org.forgerock.opendj.rest2ldap.Rest2ldapMessages.*;
import static java.util.Arrays.asList;
import static org.forgerock.opendj.ldap.Filter.alwaysFalse;
@@ -39,6 +40,8 @@
import java.util.List;
import java.util.Set;

import org.forgerock.i18n.LocalizableMessage;
import org.forgerock.i18n.slf4j.LocalizedLogger;
import org.forgerock.json.JsonPointer;
import org.forgerock.json.JsonValue;
import org.forgerock.json.JsonValueException;
@@ -95,6 +98,7 @@
import org.forgerock.services.context.Context;
import org.forgerock.services.context.SecurityContext;
import org.forgerock.util.AsyncFunction;

import org.forgerock.util.Function;
import org.forgerock.util.promise.ExceptionHandler;
import org.forgerock.util.promise.Promise;
@@ -109,6 +113,9 @@
 * resource collection to LDAP entries beneath a base DN.
 */
final class LDAPCollectionResourceProvider implements CollectionResourceProvider {

    private static final LocalizedLogger logger = LocalizedLogger.getLoggerForThisClass();

    /** Dummy exception used for signalling search success. */
    private static final ResourceException SUCCESS = new UncategorizedException(0, null, null);

@@ -171,7 +178,9 @@
            oldPassword = jsonContent.get("oldPassword").asString();
            newPassword = jsonContent.get("newPassword").asString();
        } catch (JsonValueException e) {
            final ResourceException ex = newBadRequestException(ERR_PASSWORD_MODIFY_REQUEST_IS_INVALID.get(), e);
            final LocalizableMessage msg = ERR_PASSWORD_MODIFY_REQUEST_IS_INVALID.get();
            final ResourceException ex = newBadRequestException(msg, e);
            logger.error(msg, e);
            return Promises.newExceptionPromise(ex);
        }

@@ -233,6 +242,7 @@
                                    request.getNewResourceId(),
                                    addRequest);
                        } catch (final ResourceException e) {
                            logger.error(raw(e.getLocalizedMessage()), e);
                            return Promises.newExceptionPromise(e);
                        }
                        if (config.readOnUpdatePolicy() == CONTROLS) {
@@ -669,7 +679,7 @@
                                        cookie = control.getCookie().toBase64String();
                                    }
                                } catch (final DecodeException e) {
                                    // FIXME: need some logging.
                                    logger.error(ERR_DECODING_CONTROL.get(e.getLocalizedMessage()), e);
                                }
                            }
                            completeIfNecessary(SUCCESS, promise);
@@ -930,7 +940,7 @@
                        }
                    }
                } catch (final DecodeException e) {
                    // FIXME: log something?
                    logger.error(ERR_DECODING_CONTROL.get(e.getLocalizedMessage()), e);
                    entry = null;
                }
                if (entry != null) {

 opendj-rest2ldap/src/main/java/org/forgerock/opendj/rest2ldap/Rest2LDAPHttpApplication.java

@@ -60,6 +60,8 @@
import org.forgerock.http.handler.HttpClientHandler;
import org.forgerock.http.io.Buffer;
import org.forgerock.http.protocol.Headers;
import org.forgerock.i18n.LocalizableMessage;
import org.forgerock.i18n.slf4j.LocalizedLogger;
import org.forgerock.json.JsonValue;
import org.forgerock.json.resource.RequestHandler;
import org.forgerock.json.resource.Router;
@@ -81,8 +83,6 @@
import org.forgerock.util.promise.Promise;
import org.forgerock.util.time.Duration;
import org.forgerock.util.time.TimeService;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

/** Rest2ldap HTTP application. */
public class Rest2LDAPHttpApplication implements HttpApplication {
@@ -101,7 +101,7 @@
    private static final String CACHE_ENABLED = "enabled";
    private static final String CACHE_EXPIRATION = "cacheExpiration";

    private static final Logger LOG = LoggerFactory.getLogger(Rest2LDAPHttpApplication.class);
    private static final LocalizedLogger logger = LocalizedLogger.getLoggerForThisClass();

    /** URL to the JSON configuration file. */
    protected final URL configurationUrl;
@@ -178,12 +178,13 @@
            configureConnectionFactories(configuration.get("ldapConnectionFactories"));
            return Handlers.chainOf(
                    CrestHttp.newHttpHandler(configureRest2Ldap(configuration)),
                    new ErrorLoggerFilter(),
                    buildAuthorizationFilter(configuration.get("authorization").required()));
        } catch (final Exception e) {
            final String errorMsg = ERR_FAIL_PARSE_CONFIGURATION.get(e.getLocalizedMessage()).toString();
            LOG.error(errorMsg, e);
            final LocalizableMessage errorMsg = ERR_FAIL_PARSE_CONFIGURATION.get(e.getLocalizedMessage());
            logger.error(errorMsg, e);
            stop();
            throw new HttpApplicationException(errorMsg, e);
            throw new HttpApplicationException(errorMsg.toString(), e);
        }
    }


 opendj-rest2ldap/src/main/java/org/forgerock/opendj/rest2ldap/authz/CachedReadConnectionDecorator.java

@@ -37,9 +37,13 @@
import org.forgerock.opendj.ldap.requests.SearchRequest;
import org.forgerock.opendj.ldap.responses.BindResult;
import org.forgerock.opendj.ldap.responses.ExtendedResult;
import org.forgerock.opendj.ldap.responses.Response;
import org.forgerock.opendj.ldap.responses.Result;
import org.forgerock.opendj.ldap.responses.SearchResultEntry;
import org.forgerock.opendj.ldap.responses.SearchResultReference;
import org.forgerock.util.promise.ResultHandler;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

/**
 * Cache entries by intercepting the result of base search requests. Entries in cache are automatically evicted if their
@@ -48,6 +52,21 @@
 */
final class CachedReadConnectionDecorator extends AbstractAsynchronousConnectionDecorator {

    private static final Logger logger = LoggerFactory.getLogger(CachedReadConnectionDecorator.class);

    private static final ResultHandler<Response> RESPONSE_LOGGER = new ResultHandler<Response>() {
        @Override
        public void handleResult(final Response response) {
            traceLog(response);
        }
    };

    private static void traceLog(final Object o) {
        if (logger.isTraceEnabled()) {
            logger.trace(o.toString());
        }
    }

    @SuppressWarnings("serial")
    private final Map<DN, CachedRead> cachedReads = new LinkedHashMap<DN, CachedRead>() {
        private static final int MAX_CACHED_ENTRIES = 32;
@@ -167,8 +186,9 @@
         * Simple brute force implementation in case the bind operation
         * modifies an entry: clear the cachedReads.
         */
        traceLog(request);
        evictAll();
        return delegate.bindAsync(request, intermediateResponseHandler);
        return delegate.bindAsync(request, intermediateResponseHandler).thenOnResult(RESPONSE_LOGGER);
    }

    private void evictAll() {
@@ -184,15 +204,17 @@
         * Simple brute force implementation in case the extended
         * operation modifies an entry: clear the cachedReads.
         */
        traceLog(request);
        evictAll();
        return delegate.extendedRequestAsync(request, intermediateResponseHandler);
        return delegate.extendedRequestAsync(request, intermediateResponseHandler).thenOnResult(RESPONSE_LOGGER);
    }

    @Override
    public LdapPromise<Result> modifyAsync(ModifyRequest request,
            IntermediateResponseHandler intermediateResponseHandler) {
        traceLog(request);
        evict(request.getName());
        return delegate.modifyAsync(request, intermediateResponseHandler);
        return delegate.modifyAsync(request, intermediateResponseHandler).thenOnResult(RESPONSE_LOGGER);
    }

    private void evict(final DN name) {
@@ -204,18 +226,20 @@
    @Override
    public LdapPromise<Result> deleteAsync(DeleteRequest request,
            IntermediateResponseHandler intermediateResponseHandler) {
        traceLog(request);
        // Simple brute force implementation: clear the cachedReads.
        if (request.containsControl(SubtreeDeleteRequestControl.OID)) {
            evictAll();
        } else {
            evict(request.getName());
        }
        return delegate.deleteAsync(request, intermediateResponseHandler);
        return delegate.deleteAsync(request, intermediateResponseHandler).thenOnResult(RESPONSE_LOGGER);
    }

    @Override
    public LdapPromise<Result> modifyDNAsync(ModifyDNRequest request,
            IntermediateResponseHandler intermediateResponseHandler) {
        traceLog(request);
        // Simple brute force implementation: clear the cachedReads.
        evictAll();
        return delegate.modifyDNAsync(request, intermediateResponseHandler);
@@ -229,8 +253,10 @@
         * object), or if the search request passed in an intermediate
         * response handler.
         */
        traceLog(request);
        if (!request.getScope().equals(SearchScope.BASE_OBJECT) || intermediateResponseHandler != null) {
            return delegate.searchAsync(request, intermediateResponseHandler, entryHandler);
            return delegate.searchAsync(request, intermediateResponseHandler, entryHandler)
                           .thenOnResult(RESPONSE_LOGGER);
        }

        // This is a read request and a candidate for caching.
@@ -252,7 +278,7 @@
                    .searchAsync(request, intermediateResponseHandler, pendingCachedRead)
                    .thenOnResult(pendingCachedRead).thenOnException(pendingCachedRead);
            pendingCachedRead.setPromise(promise);
            return promise;
            return promise.thenOnResult(RESPONSE_LOGGER);
        }
    }
}

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

@@ -58,6 +58,7 @@
import org.forgerock.opendj.config.server.ConfigurationChangeListener;
import org.forgerock.opendj.ldap.DN;
import org.forgerock.opendj.ldap.ResultCode;
import org.forgerock.opendj.rest2ldap.ErrorLoggerFilter;
import org.forgerock.opendj.server.config.server.ConnectionHandlerCfg;
import org.forgerock.opendj.server.config.server.HTTPConnectionHandlerCfg;
import org.forgerock.services.context.Context;
@@ -909,7 +910,8 @@
    {
      return Handlers.chainOf(
          serverContext.getHTTPRouter(),
          new HttpLogFilter(serverContext),
          new HttpAccessLogFilter(serverContext),
          new ErrorLoggerFilter(),
          new ExecuteInWorkerThreadFilter(),
          new AllowDenyFilter(currentConfig.getDeniedClient(), currentConfig.getAllowedClient()),
          new CommonAuditTransactionIdFilter(serverContext),

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

File was renamed from opendj-server-legacy/src/main/java/org/opends/server/protocols/http/HttpLogFilter.java
@@ -15,16 +15,11 @@
 */
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;
@@ -34,13 +29,11 @@
 * Creates and inject a {@link HttpLogContext} containing information that'll be logged once the request has been
 * processed.
 */
final class HttpLogFilter implements Filter
final class HttpAccessLogFilter implements Filter
{
  private static final LocalizedLogger logger = LocalizedLogger.getLoggerForThisClass();

  private final ServerContext serverContext;

  HttpLogFilter(final ServerContext serverContext)
  HttpAccessLogFilter(final ServerContext serverContext)
  {
    this.serverContext = serverContext;
  }
@@ -49,30 +42,13 @@
  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>()
    return next.handle(logContext, request).thenOnResult(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)));
  }
}

 pom.xml

@@ -394,6 +394,7 @@
                            <disabledFile>**/THIRDPARTYREADME.txt</disabledFile>
                            <disabledFile>legal-notices/CDDLv1_0.txt</disabledFile>
                            <disabledFile>**/tests/unit-tests-testng/resource/config-changes.ldif</disabledFile>
                            <disabledFile>opendj-rest2ldap-servlet/src/main/webapp/WEB-INF/classes/logging.properties</disabledFile>
                        </disabledFiles>
                    </configuration>
                </plugin>