Merge pull request #586 from swisspost/feature/issue585_delta_request…

…_log

Feature/issue585 delta request log

gateleen-delta/src/main/java/org/swisspush/gateleen/delta/DeltaHandler.java

@@ -6,6 +6,8 @@
 import io.vertx.core.AsyncResult;
 import io.vertx.core.Handler;
 import io.vertx.core.MultiMap;
+import io.vertx.core.Vertx;
+import io.vertx.core.buffer.Buffer;
 import io.vertx.core.http.*;
 import io.vertx.core.json.JsonArray;
 import io.vertx.core.json.JsonObject;
@@ -17,13 +19,17 @@
 import org.swisspush.gateleen.core.util.*;
 import org.swisspush.gateleen.core.util.ExpansionDeltaUtil.CollectionResourceContainer;
 import org.swisspush.gateleen.core.util.ExpansionDeltaUtil.SlashHandling;
+import org.swisspush.gateleen.logging.LogAppenderRepository;
+import org.swisspush.gateleen.logging.LoggingHandler;
+import org.swisspush.gateleen.logging.LoggingResourceManager;
 import org.swisspush.gateleen.routing.Router;
 import org.swisspush.gateleen.routing.Rule;
 import org.swisspush.gateleen.routing.RuleFeaturesProvider;
 import org.swisspush.gateleen.routing.RuleProvider;
 
 import java.util.*;
 
+import static org.swisspush.gateleen.logging.LoggingHandler.SKIP_LOGGING_HEADER;
 import static org.swisspush.gateleen.routing.RuleFeatures.Feature.DELTA_ON_BACKEND;
 
 /**
@@ -54,18 +60,28 @@ public class DeltaHandler implements RuleProvider.RuleChangesObserver {
     private boolean rejectLimitOffsetRequests;
 
     private RuleProvider ruleProvider;
+
+    private final Vertx vertx;
+    private final LoggingResourceManager loggingResourceManager;
+    private final LogAppenderRepository logAppenderRepository;
     private RuleFeaturesProvider ruleFeaturesProvider = new RuleFeaturesProvider(new ArrayList<>());
 
-    public DeltaHandler(RedisProvider redisProvider, HttpClient httpClient, RuleProvider ruleProvider) {
-        this(redisProvider, httpClient, ruleProvider, false);
+    public DeltaHandler(Vertx vertx, RedisProvider redisProvider, HttpClient httpClient, RuleProvider ruleProvider,
+                        LoggingResourceManager loggingResourceManager, LogAppenderRepository logAppenderRepository) {
+        this(vertx,redisProvider, httpClient, ruleProvider, loggingResourceManager, logAppenderRepository, false);
     }
 
-    public DeltaHandler(RedisProvider redisProvider, HttpClient httpClient, RuleProvider ruleProvider, boolean rejectLimitOffsetRequests) {
+    public DeltaHandler(Vertx vertx, RedisProvider redisProvider, HttpClient httpClient, RuleProvider ruleProvider,
+                        LoggingResourceManager loggingResourceManager, LogAppenderRepository logAppenderRepository,
+                        boolean rejectLimitOffsetRequests) {
+        this.vertx = vertx;
         this.redisProvider = redisProvider;
         this.httpClient = httpClient;
         this.rejectLimitOffsetRequests = rejectLimitOffsetRequests;
 
         this.ruleProvider = ruleProvider;
+        this.loggingResourceManager = loggingResourceManager;
+        this.logAppenderRepository = logAppenderRepository;
         this.ruleProvider.registerObserver(this);
     }
 
@@ -284,6 +300,9 @@ private DeltaResourcesContainer getDeltaResourceNames(List<String> subResourceNa
     private void handleCollectionGET(final HttpServerRequest request, final String updateId, final Logger log) {
         request.pause();
 
+        final LoggingHandler loggingHandler = new LoggingHandler(loggingResourceManager, logAppenderRepository, request, vertx.eventBus());
+        loggingHandler.request(request.headers());
+
         final HttpMethod method = HttpMethod.GET;
         final String targetUri = ExpansionDeltaUtil.constructRequestUri(request.path(), request.params(), null, null, SlashHandling.KEEP);
         log.debug("constructed uri for request: {}", targetUri);
@@ -299,6 +318,7 @@ private void handleCollectionGET(final HttpServerRequest request, final String u
             cReq.headers().setAll(request.headers());
             // add a marker header to signalize, that in the next loop of the mainverticle we should pass the deltahandler
             cReq.headers().set(DELTA_BACKEND_HEADER, "");
+            cReq.headers().set(SKIP_LOGGING_HEADER, "true");
             cReq.headers().set("Accept", "application/json");
             cReq.setChunked(true);
             request.handler(cReq::write);
@@ -307,6 +327,8 @@ private void handleCollectionGET(final HttpServerRequest request, final String u
                     HttpClientResponse cRes = asyncResult1.result();
                     HttpServerRequestUtil.prepareResponse(request, cRes);
 
+                    loggingHandler.setResponse(cRes);
+
                     if (cRes.headers().contains(DELTA_HEADER)) {
                         cRes.handler(data -> request.response().write(data));
                         cRes.endHandler(v1 -> request.response().end());
@@ -327,7 +349,7 @@ private void handleCollectionGET(final HttpServerRequest request, final String u
                                     log.trace("DeltaHandler: deltaResourceKeys for targetUri ({}): {}", targetUri, deltaResourceKeys);
                                 }
 
-                                if (deltaResourceKeys.size() > 0) {
+                                if (!deltaResourceKeys.isEmpty()) {
                                     if (log.isTraceEnabled()) {
                                         log.trace("DeltaHandler: targetUri ({}) using mget command.", targetUri);
                                     }
@@ -345,9 +367,12 @@ private void handleCollectionGET(final HttpServerRequest request, final String u
 
                                         JsonObject result = buildResultJsonObject(deltaResourcesContainer.getResourceNames(),
                                                 dataContainer.getCollectionName());
+                                        String responseBody = result.toString();
                                         request.response().putHeader(DELTA_HEADER,
                                                 "" + deltaResourcesContainer.getMaxUpdateId());
-                                        request.response().end(result.toString());
+                                        loggingHandler.appendResponsePayload(Buffer.buffer(responseBody));
+                                        loggingHandler.log();
+                                        request.response().end(responseBody);
                                     })).onFailure(event -> {
                                         log.error("Redis: handleCollectionGET failed", event);
                                         handleError(request, "error reading delta information");

gateleen-delta/src/test/java/org/swisspush/gateleen/delta/DeltaHandlerTest.java

@@ -1,9 +1,6 @@
 package org.swisspush.gateleen.delta;
 
-import io.vertx.core.AsyncResult;
-import io.vertx.core.Future;
-import io.vertx.core.Handler;
-import io.vertx.core.MultiMap;
+import io.vertx.core.*;
 import io.vertx.core.http.HttpMethod;
 import io.vertx.core.http.HttpServerRequest;
 import io.vertx.core.http.HttpServerResponse;
@@ -19,6 +16,8 @@
 import org.swisspush.gateleen.core.http.DummyHttpServerResponse;
 import org.swisspush.gateleen.core.redis.RedisProvider;
 import org.swisspush.gateleen.core.util.StatusCode;
+import org.swisspush.gateleen.logging.LogAppenderRepository;
+import org.swisspush.gateleen.logging.LoggingResourceManager;
 import org.swisspush.gateleen.routing.Router;
 import org.swisspush.gateleen.routing.Rule;
 import org.swisspush.gateleen.routing.RuleProvider;
@@ -36,6 +35,9 @@ public class DeltaHandlerTest {
     private RedisAPI redisAPI;
     private RedisProvider redisProvider;
     private RuleProvider ruleProvider;
+    private Vertx vertx;
+    private LoggingResourceManager loggingResourceManager;
+    private LogAppenderRepository logAppenderRepository;
     private Router router = mock(Router.class);
     private HttpServerRequest request;
     private HttpServerResponse response;
@@ -44,6 +46,9 @@ public class DeltaHandlerTest {
     @Before
     public void before() {
         redisAPI = mock(RedisAPI.class);
+        vertx = mock(Vertx.class);
+        loggingResourceManager = mock(LoggingResourceManager.class);
+        logAppenderRepository = mock(LogAppenderRepository.class);
 
         redisProvider = mock(RedisProvider.class);
         when(redisProvider.redis()).thenReturn(Future.succeededFuture(redisAPI));
@@ -69,7 +74,7 @@ public void before() {
 
     @Test
     public void testIsDeltaRequest(TestContext context) {
-        DeltaHandler deltaHandler = new DeltaHandler(redisProvider, null, ruleProvider);
+        DeltaHandler deltaHandler = new DeltaHandler(vertx, redisProvider, null, ruleProvider, loggingResourceManager, logAppenderRepository);
         deltaHandler.rulesChanged(List.of(
                 rule("/gateleen/server/res_1", false),
                 rule("/gateleen/server/res_2", true))
@@ -152,7 +157,7 @@ public void testIsDeltaRequest(TestContext context) {
 
     @Test
     public void testDeltaNoExpiry() {
-        DeltaHandler deltaHandler = new DeltaHandler(redisProvider, null, ruleProvider);
+        DeltaHandler deltaHandler = new DeltaHandler(vertx, redisProvider, null, ruleProvider, loggingResourceManager, logAppenderRepository);
         deltaHandler.handle(request, router);
 
         verify(redisAPI, times(1)).set(eq(Arrays.asList("delta:resources:a:b:c", "555")), any());
@@ -163,7 +168,7 @@ public void testDeltaNoExpiry() {
     public void testDeltaWithExpiry() {
         requestHeaders.add("x-expire-after", "123");
 
-        DeltaHandler deltaHandler = new DeltaHandler(redisProvider, null, ruleProvider);
+        DeltaHandler deltaHandler = new DeltaHandler(vertx, redisProvider, null, ruleProvider, loggingResourceManager, logAppenderRepository);
         deltaHandler.handle(request, router);
 
         verify(redisAPI, times(1)).setex(eq("delta:resources:a:b:c"), eq("123"), eq("555"), any());
@@ -182,7 +187,7 @@ public void testFailingRedisProviderAccess(TestContext context) {
         ArgumentCaptor<String> bodyCaptor = ArgumentCaptor.forClass(String.class);
         when(request.response().end(bodyCaptor.capture())).thenReturn(Future.succeededFuture());
 
-        DeltaHandler deltaHandler = new DeltaHandler(redisProvider, null, ruleProvider);
+        DeltaHandler deltaHandler = new DeltaHandler(vertx, redisProvider, null, ruleProvider, loggingResourceManager, logAppenderRepository);
         deltaHandler.handle(request, router);
 
         context.assertEquals(StatusCode.INTERNAL_SERVER_ERROR.getStatusCode(), statusCodeCaptor.getValue(), "StatusCode should be 500");
@@ -191,7 +196,7 @@ public void testFailingRedisProviderAccess(TestContext context) {
 
     @Test
     public void testRejectLimitOffsetParameters(TestContext context) {
-        DeltaHandler deltaHandler = new DeltaHandler(redisProvider, null, ruleProvider, true);
+        DeltaHandler deltaHandler = new DeltaHandler(vertx, redisProvider, null, ruleProvider, loggingResourceManager, logAppenderRepository, true);
         final DummyHttpServerResponse response = new DummyHttpServerResponse();
         DeltaRequest request = new DeltaRequest(MultiMap.caseInsensitiveMultiMap()
                 .add("delta", "0")

gateleen-logging/src/main/java/org/swisspush/gateleen/logging/LoggingHandler.java

@@ -64,6 +64,8 @@ public class LoggingHandler {
     private static final String ADDRESS = "address";
     private static final String DEFAULT = "default";
 
+    public static final String SKIP_LOGGING_HEADER = "x-skip-request-log";
+
     private Map<String, org.apache.logging.log4j.Logger> loggers = new HashMap<>();
 
     private Logger log;
@@ -76,6 +78,12 @@ public LoggingHandler(LoggingResourceManager loggingResourceManager, LogAppender
         this.log = RequestLoggerFactory.getLogger(LoggingHandler.class, request);
         ((org.apache.logging.log4j.core.Logger) LogManager.getLogger(DEFAULT_LOGGER)).setAdditive(false);
         boolean stopValidation = false;
+
+        if(request.headers().get(SKIP_LOGGING_HEADER) != null) {
+            log.info("request will not be logged because of skip log request header");
+            return;
+        }
+
         for (Map<String, String> payloadFilter : loggingResource.getPayloadFilters()) {
             if (active || stopValidation) {
                 break;

gateleen-playground/src/main/java/org/swisspush/gateleen/playground/Server.java

@@ -215,7 +215,8 @@ public void start() {
 
                 RuleProvider ruleProvider = new RuleProvider(vertx, RULES_ROOT, storage, props);
 
-                deltaHandler = new DeltaHandler(redisProvider, selfClient, ruleProvider, true);
+                deltaHandler = new DeltaHandler(vertx, redisProvider, selfClient, ruleProvider, loggingResourceManager,
+                        logAppenderRepository, true);
                 expansionHandler = new ExpansionHandler(ruleProvider, selfClient, props, ROOT);
                 copyResourceHandler = new CopyResourceHandler(selfClient, exceptionFactory, SERVER_ROOT + "/v1/copy");
                 monitoringHandler = new MonitoringHandler(vertx, storage, PREFIX, SERVER_ROOT + "/monitoring/rpr");

gateleen-test/src/test/java/org/swisspush/gateleen/AbstractTest.java

@@ -247,7 +247,7 @@ public static void setupBeforeClass(TestContext context) {
                         RunConfig.with()
                                 .cacheHandler(cacheHandler)
                                 .corsHandler(new CORSHandler())
-                                .deltaHandler(new DeltaHandler(redisProvider, selfClient, ruleProvider))
+                                .deltaHandler(new DeltaHandler(vertx, redisProvider, selfClient, ruleProvider, loggingResourceManager, logAppenderRepository))
                                 .expansionHandler(new ExpansionHandler(vertx, storage, selfClient, props, ROOT, RULES_ROOT))
                                 .hookHandler(hookHandler)
                                 .qosHandler(qosHandler)

gateleen-test/src/test/java/org/swisspush/gateleen/hook/ListenerTest.java

@@ -3,15 +3,14 @@
 import com.github.tomakehurst.wiremock.client.WireMock;
 import com.github.tomakehurst.wiremock.junit.WireMockRule;
 import com.google.common.collect.ImmutableMap;
-import org.awaitility.Awaitility;
 import io.restassured.RestAssured;
 import io.restassured.http.Header;
 import io.restassured.http.Headers;
 import io.vertx.core.json.JsonObject;
 import io.vertx.ext.unit.Async;
 import io.vertx.ext.unit.TestContext;
 import io.vertx.ext.unit.junit.VertxUnitRunner;
-import org.junit.Ignore;
+import org.awaitility.Awaitility;
 import org.junit.Rule;
 import org.junit.Test;
 import org.junit.runner.RunWith;
@@ -24,8 +23,8 @@
 
 import static com.github.tomakehurst.wiremock.client.WireMock.aResponse;
 import static com.github.tomakehurst.wiremock.stubbing.Scenario.STARTED;
-import static org.awaitility.Awaitility.await;
 import static io.restassured.RestAssured.*;
+import static org.awaitility.Awaitility.await;
 import static org.awaitility.Durations.FIVE_SECONDS;
 import static org.awaitility.Durations.TEN_SECONDS;
 import static org.hamcrest.CoreMatchers.*;

gateleen-test/src/test/java/org/swisspush/gateleen/queue/QueueTest.java

@@ -14,8 +14,8 @@
 
 import static org.awaitility.Awaitility.await;
 import static io.restassured.RestAssured.*;
-import static junit.framework.Assert.assertFalse;
-import static junit.framework.Assert.assertTrue;
+import static org.junit.Assert.assertFalse;
+import static org.junit.Assert.assertTrue;
 import static org.awaitility.Durations.*;
 import static org.hamcrest.CoreMatchers.*;