Enrich log messages with further metadata about requests

This includes:
- endpoint
- execution time
- trace id

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

9 files changed, 340 insertions, 2 deletions

diff --git a/app/src/main/java/org/onap/portalng/preferences/PreferencesApplication.java b/app/src/main/java/org/onap/portalng/preferences/PreferencesApplication.java
index 67171cd..1bbdddf 100644
--- a/app/src/main/java/org/onap/portalng/preferences/PreferencesApplication.java
+++ b/app/src/main/java/org/onap/portalng/preferences/PreferencesApplication.java
@@ -21,13 +21,14 @@
 
 package org.onap.portalng.preferences;
 
+import org.onap.portalng.preferences.logging.LoggerProperties;
 import org.onap.portalng.preferences.configuration.PreferencesConfig;
 import org.springframework.boot.SpringApplication;
 import org.springframework.boot.autoconfigure.SpringBootApplication;
 import org.springframework.boot.context.properties.EnableConfigurationProperties;
 
-@EnableConfigurationProperties(PreferencesConfig.class)
 @SpringBootApplication
+@EnableConfigurationProperties({PreferencesConfig.class, LoggerProperties.class})
 public class PreferencesApplication {
 
 	public static void main(String[] args) {
diff --git a/app/src/main/java/org/onap/portalng/preferences/logging/LogContextVariable.java b/app/src/main/java/org/onap/portalng/preferences/logging/LogContextVariable.java
new file mode 100644
index 0000000..85750ea
--- /dev/null
+++ b/app/src/main/java/org/onap/portalng/preferences/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.portalng.preferences.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/portalng/preferences/logging/LoggerProperties.java b/app/src/main/java/org/onap/portalng/preferences/logging/LoggerProperties.java
new file mode 100644
index 0000000..7bcc512
--- /dev/null
+++ b/app/src/main/java/org/onap/portalng/preferences/logging/LoggerProperties.java
@@ -0,0 +1,11 @@
+package org.onap.portalng.preferences.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/portalng/preferences/logging/LoggingHelper.java b/app/src/main/java/org/onap/portalng/preferences/logging/LoggingHelper.java
new file mode 100644
index 0000000..0131ec3
--- /dev/null
+++ b/app/src/main/java/org/onap/portalng/preferences/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.portalng.preferences.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/portalng/preferences/logging/ReactiveRequestLoggingFilter.java b/app/src/main/java/org/onap/portalng/preferences/logging/ReactiveRequestLoggingFilter.java
new file mode 100644
index 0000000..d230162
--- /dev/null
+++ b/app/src/main/java/org/onap/portalng/preferences/logging/ReactiveRequestLoggingFilter.java
@@ -0,0 +1,86 @@
+/*
+ *
+ * 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.portalng.preferences.logging;
+
+import lombok.RequiredArgsConstructor;
+import lombok.extern.slf4j.Slf4j;
+import org.springframework.boot.autoconfigure.condition.ConditionalOnWebApplication;
+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;
+
+@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/portalng/preferences/logging/StatusCode.java b/app/src/main/java/org/onap/portalng/preferences/logging/StatusCode.java
new file mode 100644
index 0000000..c565710
--- /dev/null
+++ b/app/src/main/java/org/onap/portalng/preferences/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.portalng.preferences.logging;
+
+public enum StatusCode {
+  REQUEST,
+  COMPLETE,
+  ERROR
+}
diff --git a/app/src/main/java/org/onap/portalng/preferences/logging/WebExchangeUtils.java b/app/src/main/java/org/onap/portalng/preferences/logging/WebExchangeUtils.java
new file mode 100644
index 0000000..6a56065
--- /dev/null
+++ b/app/src/main/java/org/onap/portalng/preferences/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.portalng.preferences.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 ffe174e..75654ef 100644
--- a/app/src/main/resources/application.yml
+++ b/app/src/main/resources/application.yml
@@ -44,4 +44,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 ace8c84..7092971 100644
--- a/app/src/test/resources/application.yml
+++ b/app/src/test/resources/application.yml
@@ -36,3 +36,9 @@ management:
       enabled: true
     java:
       enabled: true
+
+logger:
+  traceIdHeaderName: "X-Request-Id"
+  enabled: true
+  excludePaths:
+    - "/actuator/**"
\ No newline at end of file