From 37f521abe4e0f93523590f0475da70c6b9c4cb43 Mon Sep 17 00:00:00 2001 From: Michiel Meeuwissen Date: Fri, 24 Jan 2025 10:19:59 +0100 Subject: [PATCH] Utility for access logging. --- .../nl/vpro/logging/mdc/MDCConstants.java | 2 + vpro-shared-rs/pom.xml | 5 + .../rs/interceptors/AccessLogInterceptor.java | 102 ++++++++++++++++++ .../java/nl/vpro/util/FileInputStreamTee.java | 39 +++++++ .../java/nl/vpro/util/LoggingInputStream.java | 53 ++++----- .../util/TruncatedObservableInputStream.java | 61 +++++++++++ 6 files changed, 228 insertions(+), 34 deletions(-) create mode 100644 vpro-shared-rs/src/main/java/nl/vpro/rs/interceptors/AccessLogInterceptor.java create mode 100644 vpro-shared-util/src/main/java/nl/vpro/util/FileInputStreamTee.java create mode 100644 vpro-shared-util/src/main/java/nl/vpro/util/TruncatedObservableInputStream.java diff --git a/vpro-shared-logging/src/main/java/nl/vpro/logging/mdc/MDCConstants.java b/vpro-shared-logging/src/main/java/nl/vpro/logging/mdc/MDCConstants.java index 482f922bb..6f9d4b634 100644 --- a/vpro-shared-logging/src/main/java/nl/vpro/logging/mdc/MDCConstants.java +++ b/vpro-shared-logging/src/main/java/nl/vpro/logging/mdc/MDCConstants.java @@ -17,7 +17,9 @@ public class MDCConstants { public static final String REMOTE_ADDR = "remoteAddr"; public static final String USER_AGENT = "userAgent"; public static final String BODY = "body"; + public static final String HEADERS = "headers"; + public static final String USER_COUNT = "userCount"; public static void onBehalfOf(String user) { diff --git a/vpro-shared-rs/pom.xml b/vpro-shared-rs/pom.xml index bdd491db7..620582347 100644 --- a/vpro-shared-rs/pom.xml +++ b/vpro-shared-rs/pom.xml @@ -62,5 +62,10 @@ compile true + + org.springframework + spring-context + true + diff --git a/vpro-shared-rs/src/main/java/nl/vpro/rs/interceptors/AccessLogInterceptor.java b/vpro-shared-rs/src/main/java/nl/vpro/rs/interceptors/AccessLogInterceptor.java new file mode 100644 index 000000000..52bee73c9 --- /dev/null +++ b/vpro-shared-rs/src/main/java/nl/vpro/rs/interceptors/AccessLogInterceptor.java @@ -0,0 +1,102 @@ +package nl.vpro.rs.interceptors; + +import lombok.extern.slf4j.Slf4j; + +import java.io.IOException; +import java.nio.file.Files; +import java.nio.file.Path; +import java.util.Map; +import java.util.concurrent.ConcurrentHashMap; +import java.util.concurrent.atomic.AtomicLong; +import java.util.regex.Pattern; + +import jakarta.ws.rs.container.ContainerRequestContext; +import jakarta.ws.rs.container.ContainerRequestFilter; +import jakarta.ws.rs.ext.Provider; + +import org.slf4j.MDC; +import org.springframework.jmx.export.annotation.ManagedAttribute; +import org.springframework.jmx.export.annotation.ManagedResource; +import org.springframework.stereotype.Component; + +import nl.vpro.logging.mdc.MDCConstants; +import nl.vpro.logging.simple.Slf4jSimpleLogger; +import nl.vpro.util.*; + + +/** + * TODO: seems a more generic utility. Move it to shared. + */ +@Provider +@Component +@Slf4j +@ManagedResource +public class AccessLogInterceptor implements ContainerRequestFilter { + + private Pattern forUser = Pattern.compile("^(rcrs|npo-sourcing-service.*|functional-tests.*|nep-backend)$"); + + private Pattern forContentType = Pattern.compile("^application/(xml|json)"); + + private int truncateAfter = 2048; + + private final Map counters = new ConcurrentHashMap<>(); + + private Path filesPath = null; + + + @Override + public void filter(ContainerRequestContext requestContext) throws IOException { + + if ("POST".equals(requestContext.getMethod())) { + String contentType = requestContext.getHeaderString("content-type"); + String user = MDC.get(MDCConstants.USER_NAME); + if ((user != null && forUser.matcher(user).matches()) && + (contentType != null && forContentType.matcher(contentType).matches()) + ) { + long count = counters.computeIfAbsent(user, k -> new AtomicLong()).incrementAndGet(); + MDC.put(MDCConstants.USER_COUNT, String.valueOf(count)); + TruncatedObservableInputStream inputStream; + if (filesPath == null) { + inputStream = new LoggingInputStream(Slf4jSimpleLogger.slf4j(log), requestContext.getEntityStream()); + } else { + Path file = filesPath.resolve(user + "-" + count + ".log"); + inputStream = new FileInputStreamTee(Files.newOutputStream(file), requestContext.getEntityStream()); + } + inputStream.setTruncateAfter(truncateAfter); + requestContext.setEntityStream(inputStream); + } else { + log.trace("Not logging body for {} {}", user, contentType); + } + } + } + + @ManagedAttribute + public String getForUser() { + return forUser.pattern(); + } + + @ManagedAttribute + public void setForUser(String pattern) { + this.forUser = Pattern.compile(pattern); + } + + @ManagedAttribute + public String getForContentType() { + return forContentType.pattern(); + } + + @ManagedAttribute + public void setForContentType(String forContentType) { + this.forContentType = Pattern.compile(forContentType); + } + + @ManagedAttribute + public int getTruncateAfter() { + return truncateAfter; + } + + @ManagedAttribute + public void setTruncateAfter(int truncateAfter) { + this.truncateAfter = truncateAfter; + } +} diff --git a/vpro-shared-util/src/main/java/nl/vpro/util/FileInputStreamTee.java b/vpro-shared-util/src/main/java/nl/vpro/util/FileInputStreamTee.java new file mode 100644 index 000000000..c008a2323 --- /dev/null +++ b/vpro-shared-util/src/main/java/nl/vpro/util/FileInputStreamTee.java @@ -0,0 +1,39 @@ +package nl.vpro.util; + +import lombok.Getter; +import lombok.Setter; + +import java.io.*; + + +/** + * A wrapper for an {@link InputStream} that logs it's first bytes. + */ +@Setter +@Getter +public class FileInputStreamTee extends TruncatedObservableInputStream { + + private final OutputStream fileOutputStream; + + public FileInputStreamTee(OutputStream fileOutputStream, InputStream wrapped) { + super(wrapped); + this.fileOutputStream = fileOutputStream; + } + + @Override + void write(byte[] buffer, int offset, int effectiveLength) throws IOException { + fileOutputStream.write(buffer, offset, effectiveLength); + + } + + @Override + void write(int value) throws IOException { + fileOutputStream.write(value); + } + + @Override + void closed(long count, boolean truncated) throws IOException { + fileOutputStream.close(); + } + +} diff --git a/vpro-shared-util/src/main/java/nl/vpro/util/LoggingInputStream.java b/vpro-shared-util/src/main/java/nl/vpro/util/LoggingInputStream.java index 3373f135a..5106c535d 100644 --- a/vpro-shared-util/src/main/java/nl/vpro/util/LoggingInputStream.java +++ b/vpro-shared-util/src/main/java/nl/vpro/util/LoggingInputStream.java @@ -6,8 +6,6 @@ import java.io.*; import java.nio.charset.StandardCharsets; -import org.apache.commons.io.input.ObservableInputStream; - import nl.vpro.logging.simple.SimpleLogger; @@ -16,42 +14,29 @@ */ @Setter @Getter -public class LoggingInputStream extends ObservableInputStream { +public class LoggingInputStream extends TruncatedObservableInputStream { + - private int truncateAfter = 2048; private final ByteArrayOutputStream bytes = new ByteArrayOutputStream(); + private final SimpleLogger logger; public LoggingInputStream(SimpleLogger log, InputStream wrapped) { super(wrapped); - add(new ObservableInputStream.Observer() { - - private boolean truncated = false; - private long count = 0; - - @Override - public void data(final byte[] buffer, final int offset, final int length) { - if (bytes.size() < truncateAfter) { - int effectiveLength = Math.min(truncateAfter - bytes.size(), length); - truncated = effectiveLength < length; - bytes.write(buffer, offset, effectiveLength); - } - count += length; - } - - @Override - public void data(final int value) { - if (bytes.size() < truncateAfter) { - bytes.write(value); - } else { - truncated = true; - } - count++; - } - - @Override - public void closed() throws IOException { - log.info("body of {} bytes{}:\n{}{}\n", count, truncated ? " (truncated)" : "", bytes.toString(StandardCharsets.UTF_8), truncated ? "..." : ""); - } - }); + this.logger = log; + } + + @Override + void write(byte[] buffer, int offset, int length) throws IOException { + bytes.write(buffer, offset, length); + } + + @Override + void write(int value) throws IOException { + bytes.write(value); + } + @Override + void closed(long count, boolean truncated) throws IOException { + logger.info("body of {} bytes{}:\n{}{}\n", count, truncated ? " (truncated)" : "", bytes.toString(StandardCharsets.UTF_8), truncated ? "..." : ""); + } } diff --git a/vpro-shared-util/src/main/java/nl/vpro/util/TruncatedObservableInputStream.java b/vpro-shared-util/src/main/java/nl/vpro/util/TruncatedObservableInputStream.java new file mode 100644 index 000000000..d6305355f --- /dev/null +++ b/vpro-shared-util/src/main/java/nl/vpro/util/TruncatedObservableInputStream.java @@ -0,0 +1,61 @@ +package nl.vpro.util; + +import lombok.Getter; +import lombok.Setter; + +import java.io.IOException; +import java.io.InputStream; + +import org.apache.commons.io.input.ObservableInputStream; + + +/** + * A wrapper for an {@link InputStream} that observes it's first bytes. + * @since 5.5 + * @author Michiel Meeuwissen + */ +@Setter +@Getter +public abstract class TruncatedObservableInputStream extends ObservableInputStream { + + private int truncateAfter = 2048; + protected TruncatedObservableInputStream(InputStream wrapped) { + super(wrapped); + add(new Observer() { + private boolean truncated = false; + private long count = 0; + + @Override + public void data(final byte[] buffer, final int offset, final int length) throws IOException{ + if (count < truncateAfter) { + int effectiveLength = Math.min(truncateAfter - (int) count, length); + truncated = effectiveLength < length; + write(buffer, offset, effectiveLength); + } + count += length; + } + + @Override + public void data(final int value) throws IOException{ + if (count < truncateAfter) { + write(value); + } else { + truncated = true; + } + count++; + } + + @Override + public void closed() throws IOException { + TruncatedObservableInputStream.this.closed(count, true); + } + }); + } + + abstract void write(byte[] buffer, int offset, int length) throws IOException; + abstract void write(int value) throws IOException; + + void closed(long count, boolean truncated) throws IOException { + + } +}