diff --git a/build.gradle.kts b/build.gradle.kts index 6572f69..a5e4668 100644 --- a/build.gradle.kts +++ b/build.gradle.kts @@ -4,6 +4,7 @@ plugins { `java-library` `jacoco` id("io.freefair.lombok") version "8.12.1" + id("io.spring.dependency-management") version "1.1.7" } java { @@ -15,10 +16,24 @@ repositories { mavenCentral() } +val versions = mapOf( + "springBoot" to "3.4.2" +) + +dependencyManagement { + imports { + mavenBom("org.springframework.boot:spring-boot-dependencies:${versions["springBoot"]}") + } +} + dependencies { - api("com.fasterxml.jackson.core:jackson-databind:2.18.2") + api("com.fasterxml.jackson.core:jackson-databind") + api("org.springframework.boot:spring-boot-starter-web") + + implementation("ch.qos.logback:logback-classic") testImplementation("org.hamcrest:hamcrest:3.0") + testImplementation("org.mockito:mockito-core") } testing { diff --git a/src/main/java/app/quickcase/sdk/spring/logging/AccessLogFilter.java b/src/main/java/app/quickcase/sdk/spring/logging/AccessLogFilter.java new file mode 100644 index 0000000..9ce3d39 --- /dev/null +++ b/src/main/java/app/quickcase/sdk/spring/logging/AccessLogFilter.java @@ -0,0 +1,85 @@ +package app.quickcase.sdk.spring.logging; + +import java.io.IOException; +import java.time.Clock; +import java.time.Duration; +import java.time.Instant; + +import jakarta.servlet.Filter; +import jakarta.servlet.FilterChain; +import jakarta.servlet.ServletException; +import jakarta.servlet.ServletRequest; +import jakarta.servlet.ServletResponse; +import jakarta.servlet.http.HttpServletRequest; +import jakarta.servlet.http.HttpServletResponse; +import lombok.extern.slf4j.Slf4j; +import org.slf4j.spi.LoggingEventBuilder; +import org.springframework.http.HttpMethod; + +@Slf4j +public class AccessLogFilter implements Filter { + private static final String KEY_METHOD = "requestMethod"; + private static final String KEY_URI = "requestUri"; + private static final String KEY_STATUS = "responseCode"; + private static final String KEY_DURATION = "duration"; + + private final Clock clock; + + public AccessLogFilter() { + this.clock = Clock.systemDefaultZone(); + } + + public AccessLogFilter(Clock clock) { + this.clock = clock; + } + + @Override + public void doFilter(ServletRequest request, + ServletResponse response, + FilterChain chain) throws IOException, ServletException { + final HttpServletRequest httpRequest = (HttpServletRequest) request; + final HttpServletResponse httpResponse = (HttpServletResponse) response; + + final String method = httpRequest.getMethod(); + final String requestURI = httpRequest.getRequestURI(); + + log.atTrace() + .addKeyValue(KEY_METHOD, method) + .addKeyValue(KEY_URI, requestURI) + .log("Request received: {} {}", method, requestURI); + + final Instant start = clock.instant(); + + try { + chain.doFilter(request, response); + + final Duration duration = Duration.between(start, clock.instant()); + final int status = httpResponse.getStatus(); + + successLogBuilder(method) + .addKeyValue(KEY_METHOD, method) + .addKeyValue(KEY_URI, requestURI) + .addKeyValue(KEY_STATUS, status) + .addKeyValue(KEY_DURATION, duration.toMillis()) + .log("Request processed ({}) in {}ms: {} {}", status, duration.toMillis(), method, requestURI); + + } catch (Exception exception) { + final Duration duration = Duration.between(start, clock.instant()); + + log.atError() + .addKeyValue(KEY_METHOD, method) + .addKeyValue(KEY_URI, requestURI) + .addKeyValue(KEY_DURATION, duration.toMillis()) + .log("Request failed in {}ms: {} {} ", duration.toMillis(), method, requestURI); + + throw exception; + } + } + + private LoggingEventBuilder successLogBuilder (String httpMethod) { + if (HttpMethod.OPTIONS.matches(httpMethod)) { + return log.atDebug(); + } + return log.atInfo(); + } +} diff --git a/src/main/java/app/quickcase/sdk/spring/logging/LoggingConfiguration.java b/src/main/java/app/quickcase/sdk/spring/logging/LoggingConfiguration.java new file mode 100644 index 0000000..2e32198 --- /dev/null +++ b/src/main/java/app/quickcase/sdk/spring/logging/LoggingConfiguration.java @@ -0,0 +1,32 @@ +package app.quickcase.sdk.spring.logging; + +import jakarta.servlet.Filter; +import org.springframework.context.annotation.Bean; +import org.springframework.context.annotation.Configuration; +import org.springframework.core.Ordered; +import org.springframework.core.annotation.Order; + +/** + * Spring configuration class to import in web app using Spring's @Import annotation in order to enable MDC support, + * access logs and request tracing. + */ +@Configuration +public class LoggingConfiguration { + @Bean + @Order(Ordered.HIGHEST_PRECEDENCE) + public Filter mdcBoundaryFilter() { + return new MDCBoundaryFilter(); + } + + @Bean + @Order(Ordered.HIGHEST_PRECEDENCE + 1) + public Filter traceRequestFilter() { + return new TraceRequestFilter(); + } + + @Bean + @Order(Ordered.HIGHEST_PRECEDENCE + 2) + public Filter accessLogFilter() { + return new AccessLogFilter(); + } +} diff --git a/src/main/java/app/quickcase/sdk/spring/logging/MDCBoundaryFilter.java b/src/main/java/app/quickcase/sdk/spring/logging/MDCBoundaryFilter.java new file mode 100644 index 0000000..ad12e3e --- /dev/null +++ b/src/main/java/app/quickcase/sdk/spring/logging/MDCBoundaryFilter.java @@ -0,0 +1,29 @@ +package app.quickcase.sdk.spring.logging; + +import java.io.IOException; + +import jakarta.servlet.Filter; +import jakarta.servlet.FilterChain; +import jakarta.servlet.ServletException; +import jakarta.servlet.ServletRequest; +import jakarta.servlet.ServletResponse; +import org.slf4j.MDC; + +/** + * Given web apps handle requests by allocating threads from a pool and then reusing threads, we must ensure that the + * MDC values for a given request are always cleared at the end of the request. + */ +public class MDCBoundaryFilter implements Filter { + @Override + public void doFilter( + ServletRequest request, + ServletResponse response, + FilterChain chain + ) throws IOException, ServletException { + try { + chain.doFilter(request, response); + } finally { + MDC.clear(); + } + } +} diff --git a/src/main/java/app/quickcase/sdk/spring/logging/TraceRequestFilter.java b/src/main/java/app/quickcase/sdk/spring/logging/TraceRequestFilter.java new file mode 100644 index 0000000..ec409d3 --- /dev/null +++ b/src/main/java/app/quickcase/sdk/spring/logging/TraceRequestFilter.java @@ -0,0 +1,36 @@ +package app.quickcase.sdk.spring.logging; + +import java.io.IOException; +import java.util.Optional; +import java.util.UUID; + +import jakarta.servlet.Filter; +import jakarta.servlet.FilterChain; +import jakarta.servlet.ServletException; +import jakarta.servlet.ServletRequest; +import jakarta.servlet.ServletResponse; +import jakarta.servlet.http.HttpServletRequest; +import org.slf4j.MDC; + +/** + * Generate a unique trace ID per request and assign it to MDC to allow grouping of logs per request. + * If the request itself bears a custom trace ID header, this is preserved as parent trace ID. + */ +public class TraceRequestFilter implements Filter { + public static final String X_TRACE_ID = "x-trace-id"; + + @Override + public void doFilter( + ServletRequest request, + ServletResponse response, + FilterChain chain + ) throws IOException, ServletException { + final HttpServletRequest httpRequest = (HttpServletRequest) request; + final Optional traceParentId = Optional.ofNullable(httpRequest.getHeader(X_TRACE_ID)); + + MDC.put("traceId", UUID.randomUUID().toString()); + traceParentId.ifPresent(id -> MDC.put("traceParentId", id)); + + chain.doFilter(request, response); + } +} diff --git a/src/main/resources/console-json-appender.xml b/src/main/resources/console-json-appender.xml new file mode 100644 index 0000000..e1af9bb --- /dev/null +++ b/src/main/resources/console-json-appender.xml @@ -0,0 +1,22 @@ + + + + + + + + ${CONSOLE_LOG_THRESHOLD} + + + false + false + false + false + false + true + + + \ No newline at end of file diff --git a/src/main/resources/logback.xml b/src/main/resources/logback.xml new file mode 100644 index 0000000..0fd1480 --- /dev/null +++ b/src/main/resources/logback.xml @@ -0,0 +1,17 @@ + + + + + + + + + + + + + + + + + \ No newline at end of file diff --git a/src/test/java/app/quickcase/sdk/spring/logging/AccessLogFilterTest.java b/src/test/java/app/quickcase/sdk/spring/logging/AccessLogFilterTest.java new file mode 100644 index 0000000..18c5c9e --- /dev/null +++ b/src/test/java/app/quickcase/sdk/spring/logging/AccessLogFilterTest.java @@ -0,0 +1,53 @@ +package app.quickcase.sdk.spring.logging; + +import java.io.IOException; + +import jakarta.servlet.FilterChain; +import jakarta.servlet.ServletException; +import jakarta.servlet.http.HttpServletRequest; +import jakarta.servlet.http.HttpServletResponse; +import org.junit.jupiter.api.Assertions; +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Test; + +import static org.hamcrest.MatcherAssert.assertThat; +import static org.hamcrest.Matchers.is; +import static org.mockito.Mockito.*; + +class AccessLogFilterTest { + + @Test + @DisplayName("should execute filter chain") + void shouldExecuteFilterChain() throws ServletException, IOException { + var filter = new AccessLogFilter(); + + var request = mock(HttpServletRequest.class); + var response = mock(HttpServletResponse.class); + var chain = mock(FilterChain.class); + + filter.doFilter(request, response, chain); + + verify(chain).doFilter(request, response); + } + + @Test + @DisplayName("should rethrow exception") + void shouldRethrowException() throws ServletException, IOException { + var filter = new AccessLogFilter(); + + var request = mock(HttpServletRequest.class); + var response = mock(HttpServletResponse.class); + var chain = mock(FilterChain.class); + + var exception = new RuntimeException("Some exception"); + + doThrow(exception).when(chain).doFilter(request, response); + + var actualException = Assertions.assertThrows( + RuntimeException.class, + () -> filter.doFilter(request, response, chain) + ); + assertThat(actualException, is(exception)); + } + +} \ No newline at end of file