Enrich log messages with further metadata about requests

This includes:
- endpoint
- execution time
- trace id

Issue-ID: PORTALNG-69
Change-Id: I5d07c89313811875bff8c1c519464e53381b5db1
Signed-off-by: Fiete Ostkamp <Fiete.Ostkamp@telekom.de>

10 files changed, 348 insertions, 13 deletions

diff --git a/app/src/main/java/org/onap/portal/history/HistoryApplication.java b/app/src/main/java/org/onap/portal/history/HistoryApplication.java
index 21c3c4b..307d883 100644
--- a/app/src/main/java/org/onap/portal/history/HistoryApplication.java
+++ b/app/src/main/java/org/onap/portal/history/HistoryApplication.java
@@ -26,12 +26,13 @@ package org.onap.portal.history;
 
 
 import org.onap.portal.history.configuration.HistoryConfig;
+import org.onap.portal.history.logging.LoggerProperties;
 import org.springframework.boot.SpringApplication;
 import org.springframework.boot.autoconfigure.SpringBootApplication;
 import org.springframework.boot.context.properties.EnableConfigurationProperties;
 
-@EnableConfigurationProperties(HistoryConfig.class)
 @SpringBootApplication
+@EnableConfigurationProperties({HistoryConfig.class, LoggerProperties.class})
 public class HistoryApplication {
     public static void main(String[] args) {
         SpringApplication.run(HistoryApplication.class, args);
diff --git a/app/src/main/java/org/onap/portal/history/configuration/LogInterceptor.java b/app/src/main/java/org/onap/portal/history/configuration/RequestIdInterceptor.java
index 113aad8..aa1fd4e 100644
--- a/app/src/main/java/org/onap/portal/history/configuration/LogInterceptor.java
+++ b/app/src/main/java/org/onap/portal/history/configuration/RequestIdInterceptor.java
@@ -32,29 +32,23 @@ import reactor.core.publisher.Mono;
 import java.util.List;
 
 @Component
-public class LogInterceptor implements WebFilter {
-  public static final String EXCHANGE_CONTEXT_ATTRIBUTE =
-      ServerWebExchangeContextFilter.class.getName() + ".EXCHANGE_CONTEXT";
+public class RequestIdInterceptor implements WebFilter {
+  public static final String EXCHANGE_CONTEXT_ATTRIBUTE = ServerWebExchangeContextFilter.class.getName()
+      + ".EXCHANGE_CONTEXT";
 
   public static final String X_REQUEST_ID = "X-Request-Id";
 
   /**
-   * Override a web filter to write log entries for every request and response and add header in response with X_REQUEST_ID
+   * Override a web filter to write log entries for every request and response and
+   * add header in response with X_REQUEST_ID
    */
   @Override
   public Mono<Void> filter(ServerWebExchange exchange, WebFilterChain chain) {
     List<String> xRequestIdList = exchange.getRequest().getHeaders().get(X_REQUEST_ID);
     if (xRequestIdList != null && !xRequestIdList.isEmpty()) {
       String xRequestId = xRequestIdList.get(0);
-      Logger.requestLog( xRequestId, exchange.getRequest().getMethod(), exchange.getRequest().getURI());
-      
       exchange.getResponse().getHeaders().add(X_REQUEST_ID, xRequestId);
-      exchange.getResponse().beforeCommit(() -> {
-        Logger.responseLog(xRequestId,exchange.getResponse().getStatusCode());
-        return Mono.empty();
-      });
     }
-
     return chain
         .filter(exchange)
         .contextWrite(cxt -> cxt.put(EXCHANGE_CONTEXT_ATTRIBUTE, exchange));
diff --git a/app/src/main/java/org/onap/portal/history/logging/LogContextVariable.java b/app/src/main/java/org/onap/portal/history/logging/LogContextVariable.java
new file mode 100644
index 0000000..76cb29e
--- /dev/null
+++ b/app/src/main/java/org/onap/portal/history/logging/LogContextVariable.java
@@ -0,0 +1,40 @@
+/*
+ *
+ * Copyright (c) 2023. Deutsche Telekom AG
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ *
+ * SPDX-License-Identifier: Apache-2.0
+ *
+ *
+ */
+
+package org.onap.portal.history.logging;
+
+import lombok.Getter;
+
+@Getter
+public enum LogContextVariable {
+  TRACE_ID("trace_id"),
+  STATUS("status"),
+  NORTHBOUND_METHOD("northbound.method"),
+  NORTHBOUND_URL("northbound.url"),
+  EXECUTION_TIME("execution.time_ms"),
+  HTTP_STATUS("httpStatus");
+
+  private final String variableName;
+
+  LogContextVariable(String variableName) {
+    this.variableName = variableName;
+  }
+}
diff --git a/app/src/main/java/org/onap/portal/history/logging/LoggerProperties.java b/app/src/main/java/org/onap/portal/history/logging/LoggerProperties.java
new file mode 100644
index 0000000..c142b4f
--- /dev/null
+++ b/app/src/main/java/org/onap/portal/history/logging/LoggerProperties.java
@@ -0,0 +1,11 @@
+package org.onap.portal.history.logging;
+
+import java.util.List;
+
+import org.springframework.boot.context.properties.ConfigurationProperties;
+
+@ConfigurationProperties("logger")
+public record LoggerProperties(
+    String traceIdHeaderName,
+    Boolean enabled, List<String> excludePaths) {
+}
\ No newline at end of file
diff --git a/app/src/main/java/org/onap/portal/history/logging/LoggingHelper.java b/app/src/main/java/org/onap/portal/history/logging/LoggingHelper.java
new file mode 100644
index 0000000..e587959
--- /dev/null
+++ b/app/src/main/java/org/onap/portal/history/logging/LoggingHelper.java
@@ -0,0 +1,68 @@
+/*
+ *
+ * Copyright (c) 2023. Deutsche Telekom AG
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ *
+ * SPDX-License-Identifier: Apache-2.0
+ *
+ *
+ */
+
+package org.onap.portal.history.logging;
+
+import lombok.AccessLevel;
+import lombok.NoArgsConstructor;
+import org.slf4j.Logger;
+import org.slf4j.MDC;
+
+import java.util.Map;
+import java.util.function.BiConsumer;
+
+@NoArgsConstructor(access = AccessLevel.PRIVATE)
+public class LoggingHelper {
+  public static void error(
+      Logger logger, Map<LogContextVariable, String> metadata, String message, Object... args) {
+    log(logger::error, metadata, message, args);
+  }
+
+  public static void debug(
+      Logger logger, Map<LogContextVariable, String> metadata, String message, Object... args) {
+    log(logger::debug, metadata, message, args);
+  }
+
+  public static void info(
+      Logger logger, Map<LogContextVariable, String> metadata, String message, Object... args) {
+    log(logger::info, metadata, message, args);
+  }
+
+  public static void warn(
+      Logger logger, Map<LogContextVariable, String> metadata, String message, Object... args) {
+    log(logger::warn, metadata, message, args);
+  }
+
+  public static void trace(
+      Logger logger, Map<LogContextVariable, String> metadata, String message, Object... args) {
+    log(logger::trace, metadata, message, args);
+  }
+
+  private static void log(
+      BiConsumer<String, Object[]> logMethod,
+      Map<LogContextVariable, String> metadata,
+      String message,
+      Object... args) {
+    metadata.forEach((variable, value) -> MDC.put(variable.getVariableName(), value));
+    logMethod.accept(message, args);
+    MDC.clear();
+  }
+}
diff --git a/app/src/main/java/org/onap/portal/history/logging/ReactiveRequestLoggingFilter.java b/app/src/main/java/org/onap/portal/history/logging/ReactiveRequestLoggingFilter.java
new file mode 100644
index 0000000..059e573
--- /dev/null
+++ b/app/src/main/java/org/onap/portal/history/logging/ReactiveRequestLoggingFilter.java
@@ -0,0 +1,89 @@
+/*
+ *
+ * Copyright (c) 2023. Deutsche Telekom AG
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ *
+ * SPDX-License-Identifier: Apache-2.0
+ *
+ *
+ */
+
+package org.onap.portal.history.logging;
+
+import lombok.RequiredArgsConstructor;
+import lombok.extern.slf4j.Slf4j;
+import org.springframework.beans.factory.annotation.Value;
+import org.springframework.boot.autoconfigure.condition.ConditionalOnWebApplication;
+import org.springframework.boot.context.properties.EnableConfigurationProperties;
+import org.springframework.stereotype.Component;
+import org.springframework.web.server.ServerWebExchange;
+import org.springframework.web.server.WebFilter;
+import org.springframework.web.server.WebFilterChain;
+import reactor.core.publisher.Mono;
+
+import java.time.Duration;
+import java.time.LocalDateTime;
+import java.util.List;
+
+@Slf4j
+@Component
+@RequiredArgsConstructor
+@ConditionalOnWebApplication(type = ConditionalOnWebApplication.Type.REACTIVE)
+public class ReactiveRequestLoggingFilter implements WebFilter {
+
+  private final LoggerProperties loggerProperties;
+
+  @Override
+  public Mono<Void> filter(ServerWebExchange exchange, WebFilterChain chain) {
+    if (loggingDisabled(exchange)) {
+      return chain.filter(exchange);
+    }
+
+    var logMessageMetadata =
+        WebExchangeUtils.getRequestMetadata(exchange, loggerProperties.traceIdHeaderName());
+
+    LoggingHelper.info(log, logMessageMetadata, "RECEIVED");
+
+    var invocationStart = LocalDateTime.now();
+    return chain
+        .filter(exchange)
+        .doOnTerminate(
+            () -> {
+              logMessageMetadata.put(
+                  LogContextVariable.STATUS,
+                  exchange.getResponse().getStatusCode().isError()
+                      ? StatusCode.ERROR.name()
+                      : StatusCode.COMPLETE.name());
+              logMessageMetadata.put(
+                  LogContextVariable.HTTP_STATUS,
+                  String.valueOf(exchange.getResponse().getStatusCode().value()));
+              logMessageMetadata.put(
+                  LogContextVariable.EXECUTION_TIME,
+                  String.valueOf(
+                      Duration.between(invocationStart, LocalDateTime.now()).toMillis()));
+            })
+        .doOnSuccess(res -> LoggingHelper.info(log, logMessageMetadata, "FINISHED"))
+        .doOnError(
+            ex -> LoggingHelper.warn(log, logMessageMetadata, "FAILED: {}", ex.getMessage()));
+  }
+
+  private boolean loggingDisabled(ServerWebExchange exchange) {
+    boolean loggingDisabled = loggerProperties.enabled() == null || !loggerProperties.enabled();
+
+    boolean urlShouldBeSkipped =
+        WebExchangeUtils.matchUrlsPatternsToPath(loggerProperties.excludePaths(), exchange.getRequest().getPath().value());
+
+    return loggingDisabled || urlShouldBeSkipped;
+  }
+}
diff --git a/app/src/main/java/org/onap/portal/history/logging/StatusCode.java b/app/src/main/java/org/onap/portal/history/logging/StatusCode.java
new file mode 100644
index 0000000..1c93bd9
--- /dev/null
+++ b/app/src/main/java/org/onap/portal/history/logging/StatusCode.java
@@ -0,0 +1,28 @@
+/*
+ *
+ * Copyright (c) 2023. Deutsche Telekom AG
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ *
+ * SPDX-License-Identifier: Apache-2.0
+ *
+ *
+ */
+
+package org.onap.portal.history.logging;
+
+public enum StatusCode {
+  REQUEST,
+  COMPLETE,
+  ERROR
+}
diff --git a/app/src/main/java/org/onap/portal/history/logging/WebExchangeUtils.java b/app/src/main/java/org/onap/portal/history/logging/WebExchangeUtils.java
new file mode 100644
index 0000000..8efda9c
--- /dev/null
+++ b/app/src/main/java/org/onap/portal/history/logging/WebExchangeUtils.java
@@ -0,0 +1,92 @@
+/*
+ *
+ * Copyright (c) 2023. Deutsche Telekom AG
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ *
+ * SPDX-License-Identifier: Apache-2.0
+ *
+ *
+ */
+
+package org.onap.portal.history.logging;
+
+import lombok.AccessLevel;
+import lombok.NoArgsConstructor;
+import org.springframework.util.AntPathMatcher;
+import org.springframework.util.PathMatcher;
+import org.springframework.web.server.ServerWebExchange;
+
+import java.util.EnumMap;
+import java.util.List;
+import java.util.Map;
+
+@NoArgsConstructor(access = AccessLevel.PRIVATE)
+public class WebExchangeUtils {
+  private static final String DEFAULT_TRACE_ID = "REQUEST_ID_IS_NOT_SET";
+  private static final String DEFAULT_REQUEST_URL = "REQUEST_URL_IS_ABSENT";
+  private static final String DEFAULT_REQUEST_METHOD = "HTTP_METHOD_IS_ABSENT";
+
+  private static final PathMatcher pathMatcher = new AntPathMatcher();
+
+  public static String getRequestId(ServerWebExchange webExchange, String traceIdHeaderName) {
+    if (webExchange == null || traceIdHeaderName == null) {
+      return DEFAULT_TRACE_ID;
+    }
+
+    var requestIdHeaders = webExchange.getRequest().getHeaders().get(traceIdHeaderName);
+    if (requestIdHeaders != null) {
+      return requestIdHeaders.stream().findAny().orElse(DEFAULT_TRACE_ID);
+    } else {
+      return DEFAULT_TRACE_ID;
+    }
+  }
+
+  public static String getRequestUrl(ServerWebExchange webExchange) {
+    if (webExchange == null) {
+      return DEFAULT_REQUEST_URL;
+    }
+    return webExchange.getRequest().getURI().toString();
+  }
+
+  public static String getRequestHttpMethod(ServerWebExchange webExchange) {
+    if (webExchange == null) {
+      return DEFAULT_REQUEST_METHOD;
+    }
+    return webExchange.getRequest().getMethod().name();
+  }
+
+  public static boolean matchUrlPatternToPath(String pattern, String path) {
+    return pathMatcher.match(pattern, path);
+  }
+
+  public static boolean matchUrlsPatternsToPath(List<String> patterns, String path) {
+    return patterns != null
+        && patterns.stream().anyMatch(pathPattern -> matchUrlPatternToPath(pathPattern, path));
+  }
+
+  public static Map<LogContextVariable, String> getRequestMetadata(
+      ServerWebExchange exchange, String traceIdHeaderName) {
+    var traceId = WebExchangeUtils.getRequestId(exchange, traceIdHeaderName);
+    var requestMethod = WebExchangeUtils.getRequestHttpMethod(exchange);
+    var requestUrl = WebExchangeUtils.getRequestUrl(exchange);
+
+    var logMessageMetadata = new EnumMap<LogContextVariable, String>(LogContextVariable.class);
+    logMessageMetadata.put(LogContextVariable.TRACE_ID, traceId);
+    logMessageMetadata.put(LogContextVariable.STATUS, StatusCode.REQUEST.name());
+    logMessageMetadata.put(LogContextVariable.NORTHBOUND_METHOD, requestMethod);
+    logMessageMetadata.put(LogContextVariable.NORTHBOUND_URL, requestUrl);
+
+    return logMessageMetadata;
+  }
+}
diff --git a/app/src/main/resources/application.yml b/app/src/main/resources/application.yml
index 8d3ccde..15e8422 100644
--- a/app/src/main/resources/application.yml
+++ b/app/src/main/resources/application.yml
@@ -46,4 +46,10 @@ management:
       probability: 1.0 # sample every request
   zipkin:
     tracing:
-      endpoint: http://${COLLECTOR_HOST}:${COLLECTOR_PORT}/api/v2/spans
\ No newline at end of file
+      endpoint: http://${COLLECTOR_HOST}:${COLLECTOR_PORT}/api/v2/spans
+
+logger:
+  traceIdHeaderName: "X-Request-Id"
+  enabled: true
+  excludePaths:
+    - "/actuator/**"
\ No newline at end of file
diff --git a/app/src/test/resources/application.yml b/app/src/test/resources/application.yml
index db0d057..b163059 100644
--- a/app/src/test/resources/application.yml
+++ b/app/src/test/resources/application.yml
@@ -38,3 +38,9 @@ management:
       enabled: true
     java:
       enabled: true
+
+logger:
+  traceIdHeaderName: "X-Request-Id"
+  enabled: true
+  excludePaths:
+    - "/actuator/**"
\ No newline at end of file