From 32825449008a17bd6b49a1a4d9c1642e8efcdfd8 Mon Sep 17 00:00:00 2001 From: Fayupable <90789180+Fayupable@users.noreply.github.com> Date: Wed, 5 Aug 2026 15:08:03 +0300 Subject: [PATCH] Release 1.2.0: add logged-test module and JSON event emission - Add logged-test module: in-memory, thread-safe test doubles for all three output ports (InMemoryInvocationEventEmitter, InMemoryMetricsRecorder with a new RecordedMetric record, InMemoryClientInfoPort), so a consuming project can assert directly on @Logged behavior in tests instead of parsing log output or hand-rolling its own stubs. Depends only on logged-core, works with or without logged-spring on the classpath. - Add JsonInvocationEventEmitter (logged-spring): writes each MethodInvocationEvent as a single line of structured JSON through SLF4J, for applications shipping logs to Loki/Elasticsearch/Datadog and similar backends that parse each line as JSON. Uses a small hand-written JSON writer with proper string escaping instead of adding a JSON library dependency. - Update README with "Testing with logged-test" and "JSON event emission" sections, and the Modules table. Bumps version to 1.2.0. --- CHANGELOG.md | 10 +- README.md | 87 ++++++++ logged-benchmarks/dependency-reduced-pom.xml | 2 +- logged-benchmarks/pom.xml | 2 +- logged-core/pom.xml | 2 +- logged-spring/pom.xml | 2 +- .../emitter/JsonInvocationEventEmitter.java | 116 +++++++++++ .../JsonInvocationEventEmitterTest.java | 192 ++++++++++++++++++ logged-test/pom.xml | 72 +++++++ .../logged/test/InMemoryClientInfoPort.java | 52 +++++ .../test/InMemoryInvocationEventEmitter.java | 71 +++++++ .../logged/test/InMemoryMetricsRecorder.java | 70 +++++++ .../fayupable/logged/test/RecordedMetric.java | 25 +++ .../test/InMemoryClientInfoPortTest.java | 52 +++++ .../InMemoryInvocationEventEmitterTest.java | 90 ++++++++ .../test/InMemoryMetricsRecorderTest.java | 82 ++++++++ pom.xml | 3 +- 17 files changed, 924 insertions(+), 6 deletions(-) create mode 100644 logged-spring/src/main/java/com/fayupable/logged/spring/emitter/JsonInvocationEventEmitter.java create mode 100644 logged-spring/src/test/java/com/fayupable/logged/spring/emitter/JsonInvocationEventEmitterTest.java create mode 100644 logged-test/pom.xml create mode 100644 logged-test/src/main/java/com/fayupable/logged/test/InMemoryClientInfoPort.java create mode 100644 logged-test/src/main/java/com/fayupable/logged/test/InMemoryInvocationEventEmitter.java create mode 100644 logged-test/src/main/java/com/fayupable/logged/test/InMemoryMetricsRecorder.java create mode 100644 logged-test/src/main/java/com/fayupable/logged/test/RecordedMetric.java create mode 100644 logged-test/src/test/java/com/fayupable/logged/test/InMemoryClientInfoPortTest.java create mode 100644 logged-test/src/test/java/com/fayupable/logged/test/InMemoryInvocationEventEmitterTest.java create mode 100644 logged-test/src/test/java/com/fayupable/logged/test/InMemoryMetricsRecorderTest.java diff --git a/CHANGELOG.md b/CHANGELOG.md index 05f4737..8f45ad7 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -6,6 +6,13 @@ The format follows [Keep a Changelog](https://keepachangelog.com/en/1.1.0/), and ## [Unreleased] +## [1.2.0] - 2026-08-04 + +### Added + +- New `logged-test` module: in-memory, thread-safe test doubles for all three output ports — `InMemoryInvocationEventEmitter`, `InMemoryMetricsRecorder` (backed by a new `RecordedMetric` record), and `InMemoryClientInfoPort` — so a consuming project can assert directly on `@Logged` behavior in tests instead of parsing log output or hand-rolling its own stubs. Depends only on `logged-core`, so it works with or without `logged-spring` on the classpath. +- New `JsonInvocationEventEmitter` (`logged-spring`): writes each `MethodInvocationEvent` as a single line of structured JSON through SLF4J instead of `Slf4jInvocationEventEmitter`'s human-readable line, for applications shipping logs to Loki/Elasticsearch/Datadog and similar backends that parse each line as JSON. Uses a small hand-written JSON writer with proper string escaping instead of adding a JSON library dependency. + ## [1.1.0] - 2026-08-03 ### Added @@ -48,6 +55,7 @@ The format follows [Keep a Changelog](https://keepachangelog.com/en/1.1.0/), and - `logged-benchmarks`: internal JMH benchmarks measuring the aspect's overhead against a direct, uninstrumented call. - Quality gates: Pitest mutation testing (`logged-core` 100%, `logged-spring` 98%) and Checkstyle (0 violations), both enforced via `mvn verify`. -[Unreleased]: https://github.com/fayupable/logged-lib/compare/v1.1.0...HEAD +[Unreleased]: https://github.com/fayupable/logged-lib/compare/v1.2.0...HEAD +[1.2.0]: https://github.com/fayupable/logged-lib/compare/v1.1.0...v1.2.0 [1.1.0]: https://github.com/fayupable/logged-lib/compare/v1.0.0...v1.1.0 [1.0.0]: https://github.com/fayupable/logged-lib/releases/tag/v1.0.0 diff --git a/README.md b/README.md index e4b5119..a26bed2 100644 --- a/README.md +++ b/README.md @@ -33,9 +33,11 @@ public class OrderService { - [Call chain tracking](#call-chain-tracking) - [Async, `@Async`, and virtual thread support](#async-async-and-virtual-thread-support) - [Structured logging (MDC)](#structured-logging-mdc) +- [JSON event emission](#json-event-emission) - [Cross-service tracing over Kafka and RabbitMQ](#cross-service-tracing-over-kafka-and-rabbitmq) - [Cross-service tracing over HTTP](#cross-service-tracing-over-http) - [Where `@Logged` belongs](#where-logged-belongs) +- [Testing with logged-test](#testing-with-logged-test) - [Configuration](#configuration) - [Modules](#modules) - [Metrics](#metrics) @@ -269,6 +271,29 @@ logged: `FlowContextPropagatingExecutor` and `FlowContextTaskDecorator` (see [Async, `@Async`, and virtual thread support](#async-async-and-virtual-thread-support)) propagate the *entire* MDC context map across a thread hand-off, not only these four keys — so any MDC entries your own code has set (a request id from a web filter, for example) survive a thread boundary the same way this library's own do. +## JSON event emission + +The default `Slf4jInvocationEventEmitter` writes a human-readable prose line, which is easy to read at a terminal but awkward for a structured logging backend (Loki, Elasticsearch, Datadog, and similar) that parses each log line as JSON: the whole line either fails to parse or gets indexed as one opaque string field, so you cannot filter or aggregate on individual fields such as `className` or `success`. + +`JsonInvocationEventEmitter` is a drop-in alternative that writes the exact same `MethodInvocationEvent` fields as a single line of JSON instead: + +```json +{"className":"OrderService","methodName":"placeOrder","timestamp":"2026-08-04T10:00:01.052Z","durationMs":187,"success":true,"exceptionType":null,"rootCauseType":null,"callerIdentity":"user:42","traceId":"fd6a56d153407322","depth":0} +``` + +Register it in place of the default: + +```java +@Bean +InvocationEventEmitter invocationEventEmitter() { + return new JsonInvocationEventEmitter(); +} +``` + +No JSON library is used or required — every field on `MethodInvocationEvent` is a primitive, a `String`, or an `Instant`, so a small hand-written writer is enough, and this stays true to the rest of this library: no dependency is added to pick this up. String fields are escaped for quotes, backslashes, and control characters before being written, so the emitted line is always valid JSON regardless of what a class or method name happens to contain. + +Like the default emitter, successful calls are logged at `INFO` and failed calls at `WARN`, and the exception message is never included — only its simple class name, consistent with everything else this library records. + ## Cross-service tracing over Kafka and RabbitMQ Everything above — call chain tracking, MDC, async propagation — works within a single service. A call chain that crosses a message queue into a different service starts over with a brand-new `traceId` on the other side by default: nothing carries it across a Kafka or RabbitMQ message on its own. @@ -392,6 +417,66 @@ or remove @Logged from this method until reactive support is added. This is deliberate too, for a different reason than entities/repositories: a reactive type is lazy — nothing runs until something subscribes — so by the time `@Logged` could record anything, the pipeline has only been assembled, not executed. Recording at that point would silently report a near-zero duration and unconditional success no matter what the pipeline actually does once subscribed to, which is worse than not measuring it at all, since it looks like real data. Rejecting it at startup is preferred over recording something misleading. `@Logged` already supports `CompletableFuture` correctly (see [Async, `@Async`, and virtual thread support](#async-async-and-virtual-thread-support)); full reactive support (bridging `FlowContext` and MDC through Reactor's `Context`) is a substantially larger feature and not yet implemented. +## Testing with logged-test + +Asserting that `@Logged` actually observed a call correctly has historically meant either capturing and parsing log output, or hand-rolling a throwaway `InvocationEventEmitter`/`MetricsRecorder`/`IClientInfoPort` in every project that depends on this library. `logged-test` ships ready-made, thread-safe in-memory implementations of all three output ports instead, so a test can assert directly on Java objects. + +Add it as a test-scoped dependency: + +```xml + + com.fayupable + logged-test + 1.1.0 + test + +``` + +Register the ones you need as `@TestConfiguration` beans — `@ConditionalOnMissingBean` in `LoggedAutoConfiguration` picks them up in place of the real `Slf4jInvocationEventEmitter`/`MicrometerMetricsRecorder`/caller resolver automatically: + +```java +@TestConfiguration +class LoggedTestConfig { + + @Bean + InvocationEventEmitter invocationEventEmitter() { + return new InMemoryInvocationEventEmitter(); + } + + @Bean + MetricsRecorder metricsRecorder() { + return new InMemoryMetricsRecorder(); + } + + @Bean + IClientInfoPort clientInfoPort() { + return new InMemoryClientInfoPort("user:42"); + } +} + +@SpringBootTest +@Import(LoggedTestConfig.class) +class OrderServiceTest { + + @Autowired InMemoryInvocationEventEmitter emitter; + @Autowired OrderService orderService; + + @Test + void recordsSuccessfulOrderProcessing() { + orderService.processOrder(order); + + MethodInvocationEvent event = emitter.lastEvent(); + assertThat(event.methodName()).isEqualTo("processOrder"); + assertThat(event.success()).isTrue(); + assertThat(event.callerIdentity()).isEqualTo("user:42"); + } +} +``` + +The same three classes work without Spring at all, against a `LoggedAspect` (or any other interceptor) constructed directly in a plain JUnit test — `logged-test` depends on nothing but `logged-core`. + +Each class exposes `clear()` so a single instance can be reused across test methods without leaking state between them, and is backed by a `CopyOnWriteArrayList` so recording from a different thread — for example inside work wrapped by `FlowContextPropagatingExecutor` — never loses an event or corrupts the recorded list. + ## Configuration Every property below is optional and defaults to preserving the library's out-of-the-box behavior unmodified. @@ -415,10 +500,12 @@ logged: |---|---|---| | `logged-core` | nothing | ✅ | | `logged-spring` | `logged-core`, Spring Boot (all `provided`) | ✅ | +| `logged-test` | `logged-core` | ✅ | | `logged-benchmarks` | `logged-core`, `logged-spring` | ❌ internal only | - **`logged-core`** is framework-free: the `@Logged` annotation, the `MethodInvocationEvent`/`FlowContext` models, and the output ports (`InvocationEventEmitter`, `MetricsRecorder`, `IClientInfoPort`), each with a no-op default. It has zero dependencies and can be used standalone by any interception mechanism — not only Spring AOP. - **`logged-spring`** is the Spring Boot adapter: the `@Around` aspect, an SLF4J-backed emitter, a Micrometer-backed metrics recorder, a Spring Security-backed caller resolver, the startup guard described above, full auto-configuration, the `FlowContextPropagatingExecutor`/`FlowContextTaskDecorator` pair and the `RequestAttributes`/`SecurityContext` propagating decorators described in [Async, `@Async`, and virtual thread support](#async-async-and-virtual-thread-support), the MDC propagation described in [Structured logging (MDC)](#structured-logging-mdc), the `KafkaTraceHeaderCarrier`/`RabbitTraceHeaderCarrier` pair described in [Cross-service tracing over Kafka and RabbitMQ](#cross-service-tracing-over-kafka-and-rabbitmq), and the HTTP integrations (`HttpTraceClientHttpRequestInterceptor`, `FeignTraceRequestInterceptor`, `HttpTraceExchangeFilterFunction`, `HttpTraceServletFilter`, and the underlying `HttpTraceHeaderCarrier`) described in [Cross-service tracing over HTTP](#cross-service-tracing-over-http). Every Spring/Micrometer/Security/Kafka/RabbitMQ/Feign/WebFlux dependency it declares is `provided` scope, so none of it is forced onto a consuming project's dependency tree — if your application doesn't already have Micrometer, Spring Security, Kafka, RabbitMQ, Feign, or WebFlux, the corresponding feature simply falls back to a no-op, or is simply never invoked. +- **`logged-test`** provides in-memory test doubles for all three output ports, described in [Testing with logged-test](#testing-with-logged-test). It depends only on `logged-core`, so it works whether or not `logged-spring` is on the classpath. - **`logged-benchmarks`** never leaves this repository; see [Benchmarks](#benchmarks). ## Metrics diff --git a/logged-benchmarks/dependency-reduced-pom.xml b/logged-benchmarks/dependency-reduced-pom.xml index 8d5b8ba..4a3523f 100644 --- a/logged-benchmarks/dependency-reduced-pom.xml +++ b/logged-benchmarks/dependency-reduced-pom.xml @@ -3,7 +3,7 @@ logged-lib com.fayupable - 1.1.0 + 1.2.0 4.0.0 logged-benchmarks diff --git a/logged-benchmarks/pom.xml b/logged-benchmarks/pom.xml index d944963..79695a5 100644 --- a/logged-benchmarks/pom.xml +++ b/logged-benchmarks/pom.xml @@ -7,7 +7,7 @@ com.fayupable logged-lib - 1.1.0 + 1.2.0 logged-benchmarks diff --git a/logged-core/pom.xml b/logged-core/pom.xml index 087b8a7..3419a78 100644 --- a/logged-core/pom.xml +++ b/logged-core/pom.xml @@ -7,7 +7,7 @@ com.fayupable logged-lib - 1.1.0 + 1.2.0 logged-core diff --git a/logged-spring/pom.xml b/logged-spring/pom.xml index 1e1e9b6..c9ddec5 100644 --- a/logged-spring/pom.xml +++ b/logged-spring/pom.xml @@ -7,7 +7,7 @@ com.fayupable logged-lib - 1.1.0 + 1.2.0 logged-spring diff --git a/logged-spring/src/main/java/com/fayupable/logged/spring/emitter/JsonInvocationEventEmitter.java b/logged-spring/src/main/java/com/fayupable/logged/spring/emitter/JsonInvocationEventEmitter.java new file mode 100644 index 0000000..6241390 --- /dev/null +++ b/logged-spring/src/main/java/com/fayupable/logged/spring/emitter/JsonInvocationEventEmitter.java @@ -0,0 +1,116 @@ +package com.fayupable.logged.spring.emitter; + +import com.fayupable.logged.core.model.MethodInvocationEvent; +import com.fayupable.logged.core.port.InvocationEventEmitter; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; + +/** + * {@link InvocationEventEmitter} that writes each event as a single line of + * structured JSON through SLF4J, instead of the human-readable line produced + * by {@link Slf4jInvocationEventEmitter}. + * + *

This exists for applications that ship their logs to a structured + * backend (Loki, Elasticsearch, Datadog, and similar) that parses each log + * line as JSON. Emitting {@link Slf4jInvocationEventEmitter}'s prose line + * into such a backend either fails to parse or gets indexed as one opaque + * string field, losing the ability to filter or aggregate on individual + * fields (for example querying every failed call for a given + * {@code className}). This emitter writes every {@link MethodInvocationEvent} + * field as its own JSON property instead, so the backend's own JSON parser + * indexes them directly. + * + *

No JSON library is used or required: every field on + * {@link MethodInvocationEvent} is a primitive, a {@code String}, or an + * {@link java.time.Instant}, so a small hand-written writer is enough and + * keeps this class dependency-free, consistent with the rest of this + * library. String fields are escaped for quotes, backslashes, and control + * characters before being written, since {@code className}, exception type + * names, and caller identity ultimately originate from application code or + * an authenticated principal, not arbitrary user input — but escaping them + * anyway costs nothing and guarantees the emitted line is always valid JSON. + * + *

As with {@link Slf4jInvocationEventEmitter}, successful calls are + * logged at {@code INFO} and failed calls at {@code WARN}, and the + * exception message is never included, only its simple class name. + */ +public class JsonInvocationEventEmitter implements InvocationEventEmitter { + + private static final Logger log = LoggerFactory.getLogger(JsonInvocationEventEmitter.class); + + @Override + public void emit(MethodInvocationEvent event) { + String json = toJson(event); + + if (event.success()) { + log.info("{}", json); + } else { + log.warn("{}", json); + } + } + + private static String toJson(MethodInvocationEvent event) { + StringBuilder json = new StringBuilder(160); + json.append('{'); + appendString(json, "className", event.className()); + json.append(','); + appendString(json, "methodName", event.methodName()); + json.append(','); + appendString(json, "timestamp", event.timestamp().toString()); + json.append(','); + appendNumber(json, "durationMs", event.durationNanos() / 1_000_000); + json.append(','); + appendBoolean(json, "success", event.success()); + json.append(','); + appendString(json, "exceptionType", event.exceptionType()); + json.append(','); + appendString(json, "rootCauseType", event.rootCauseType()); + json.append(','); + appendString(json, "callerIdentity", event.callerIdentity()); + json.append(','); + appendString(json, "traceId", event.traceId()); + json.append(','); + appendNumber(json, "depth", event.depth()); + json.append('}'); + return json.toString(); + } + + private static void appendString(StringBuilder json, String name, String value) { + json.append('"').append(name).append('"').append(':'); + if (value == null) { + json.append("null"); + } else { + json.append('"').append(escape(value)).append('"'); + } + } + + private static void appendNumber(StringBuilder json, String name, long value) { + json.append('"').append(name).append('"').append(':').append(value); + } + + private static void appendBoolean(StringBuilder json, String name, boolean value) { + json.append('"').append(name).append('"').append(':').append(value); + } + + private static String escape(String value) { + StringBuilder escaped = new StringBuilder(value.length()); + for (int i = 0; i < value.length(); i++) { + char c = value.charAt(i); + switch (c) { + case '"' -> escaped.append("\\\""); + case '\\' -> escaped.append("\\\\"); + case '\n' -> escaped.append("\\n"); + case '\r' -> escaped.append("\\r"); + case '\t' -> escaped.append("\\t"); + default -> { + if (c < 0x20) { + escaped.append(String.format("\\u%04x", (int) c)); + } else { + escaped.append(c); + } + } + } + } + return escaped.toString(); + } +} diff --git a/logged-spring/src/test/java/com/fayupable/logged/spring/emitter/JsonInvocationEventEmitterTest.java b/logged-spring/src/test/java/com/fayupable/logged/spring/emitter/JsonInvocationEventEmitterTest.java new file mode 100644 index 0000000..83f4da3 --- /dev/null +++ b/logged-spring/src/test/java/com/fayupable/logged/spring/emitter/JsonInvocationEventEmitterTest.java @@ -0,0 +1,192 @@ +package com.fayupable.logged.spring.emitter; + +import ch.qos.logback.classic.Level; +import ch.qos.logback.classic.Logger; +import ch.qos.logback.classic.spi.ILoggingEvent; +import ch.qos.logback.core.read.ListAppender; +import com.fayupable.logged.core.model.MethodInvocationEvent; +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.BeforeEach; +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Nested; +import org.junit.jupiter.api.Test; +import org.slf4j.LoggerFactory; + +import java.time.Instant; + +import static org.assertj.core.api.Assertions.assertThat; + +@DisplayName("JsonInvocationEventEmitter") +class JsonInvocationEventEmitterTest { + + private static final String CALLER_IDENTITY = "user:42"; + + private JsonInvocationEventEmitter emitter; + private Logger logbackLogger; + private ListAppender appender; + + @BeforeEach + void setUp() { + emitter = new JsonInvocationEventEmitter(); + + logbackLogger = (Logger) LoggerFactory.getLogger(JsonInvocationEventEmitter.class); + appender = new ListAppender<>(); + appender.start(); + logbackLogger.addAppender(appender); + } + + @AfterEach + void tearDown() { + logbackLogger.detachAppender(appender); + } + + private MethodInvocationEvent successEvent() { + return new MethodInvocationEvent( + "UserService", "getUser", Instant.parse("2026-01-01T00:00:00Z"), 12_000_000L, true, null, null, + CALLER_IDENTITY, "abc123", 2 + ); + } + + private MethodInvocationEvent failureEvent(String exceptionType, String rootCauseType) { + return new MethodInvocationEvent( + "UserService", "getUser", Instant.parse("2026-01-01T00:00:00Z"), 5_000_000L, false, exceptionType, + rootCauseType, CALLER_IDENTITY, "abc123", 0 + ); + } + + private String printedMessage() { + assertThat(appender.list).hasSize(1); + String message = appender.list.get(0).getFormattedMessage(); + System.out.println("LOGGED -> " + message); + return message; + } + + @Nested + @DisplayName("on a successful call") + class SuccessfulCall { + + @Test + @DisplayName("logs at INFO level") + void logsAtInfoLevel() { + emitter.emit(successEvent()); + + assertThat(appender.list.get(0).getLevel()).isEqualTo(Level.INFO); + } + + @Test + @DisplayName("writes every field as its own JSON property") + void writesEveryFieldAsJsonProperty() { + emitter.emit(successEvent()); + + String message = printedMessage(); + + assertThat(message) + .startsWith("{").endsWith("}") + .contains("\"className\":\"UserService\"") + .contains("\"methodName\":\"getUser\"") + .contains("\"timestamp\":\"2026-01-01T00:00:00Z\"") + .contains("\"durationMs\":12,") + .contains("\"success\":true") + .contains("\"exceptionType\":null") + .contains("\"rootCauseType\":null") + .contains("\"callerIdentity\":\"user:42\"") + .contains("\"traceId\":\"abc123\"") + .contains("\"depth\":2"); + } + } + + @Nested + @DisplayName("on a failed call") + class FailedCall { + + @Test + @DisplayName("logs at WARN level") + void logsAtWarnLevel() { + emitter.emit(failureEvent("IllegalArgumentException", "IllegalArgumentException")); + + assertThat(appender.list.get(0).getLevel()).isEqualTo(Level.WARN); + } + + @Test + @DisplayName("writes exception type and root cause as JSON properties") + void writesExceptionAndRootCause() { + emitter.emit(failureEvent("IllegalArgumentException", "SQLException")); + + String message = printedMessage(); + + assertThat(message) + .contains("\"exceptionType\":\"IllegalArgumentException\"") + .contains("\"rootCauseType\":\"SQLException\""); + } + } + + @Nested + @DisplayName("string escaping") + class StringEscaping { + + @Test + @DisplayName("escapes quotes, backslashes, and control characters in string fields") + void escapesSpecialCharacters() { + MethodInvocationEvent event = new MethodInvocationEvent( + "Weird\"Class\\Name", "method\nWithNewline", Instant.parse("2026-01-01T00:00:00Z"), + 1_000_000L, true, null, null, CALLER_IDENTITY, "abc123", 0 + ); + + emitter.emit(event); + + String message = printedMessage(); + + assertThat(message) + .contains("\"className\":\"Weird\\\"Class\\\\Name\"") + .contains("\"methodName\":\"method\\nWithNewline\""); + } + + @Test + @DisplayName("escapes control characters below U+0020 that have no dedicated shorthand") + void escapesOtherControlCharacters() { + String methodNameWithControlChar = "method" + '' + "WithControlChar"; + MethodInvocationEvent event = new MethodInvocationEvent( + "UserService", methodNameWithControlChar, Instant.parse("2026-01-01T00:00:00Z"), + 1_000_000L, true, null, null, CALLER_IDENTITY, "abc123", 0 + ); + + emitter.emit(event); + + String message = printedMessage(); + + assertThat(message).contains("\"methodName\":\"method\\u0001WithControlChar\""); + } + + @Test + @DisplayName("does not escape the space character, the first non-control code point") + void doesNotEscapeSpace() { + MethodInvocationEvent event = new MethodInvocationEvent( + "UserService", "method with space", Instant.parse("2026-01-01T00:00:00Z"), + 1_000_000L, true, null, null, CALLER_IDENTITY, "abc123", 0 + ); + + emitter.emit(event); + + String message = printedMessage(); + + assertThat(message) + .contains("\"methodName\":\"method with space\"") + .doesNotContain("\\u0020"); + } + + @Test + @DisplayName("produces a single unbroken log line even when a field contains a newline") + void producesSingleLogLine() { + MethodInvocationEvent event = new MethodInvocationEvent( + "UserService", "method\nWithNewline", Instant.parse("2026-01-01T00:00:00Z"), + 1_000_000L, true, null, null, CALLER_IDENTITY, "abc123", 0 + ); + + emitter.emit(event); + + String message = printedMessage(); + + assertThat(message).doesNotContain("\n"); + } + } +} diff --git a/logged-test/pom.xml b/logged-test/pom.xml new file mode 100644 index 0000000..51a4c12 --- /dev/null +++ b/logged-test/pom.xml @@ -0,0 +1,72 @@ + + + 4.0.0 + + + com.fayupable + logged-lib + 1.2.0 + + + logged-test + jar + + logged-test + In-memory test doubles for logged-core's output ports, so a consuming project can assert on @Logged behavior without wiring a real emitter, metrics backend, or caller resolver. + + + + com.fayupable + logged-core + ${project.version} + + + + org.junit.jupiter + junit-jupiter + test + + + org.assertj + assertj-core + test + + + + + + + org.apache.maven.plugins + maven-surefire-plugin + + + org.apache.maven.plugins + maven-checkstyle-plugin + + + org.pitest + pitest-maven + + + com.fayupable.logged.test.* + + + com.fayupable.logged.test.* + + 90 + + + + pitest-mutation-coverage + verify + + mutationCoverage + + + + + + + diff --git a/logged-test/src/main/java/com/fayupable/logged/test/InMemoryClientInfoPort.java b/logged-test/src/main/java/com/fayupable/logged/test/InMemoryClientInfoPort.java new file mode 100644 index 0000000..a82a068 --- /dev/null +++ b/logged-test/src/main/java/com/fayupable/logged/test/InMemoryClientInfoPort.java @@ -0,0 +1,52 @@ +package com.fayupable.logged.test; + +import com.fayupable.logged.core.port.IClientInfoPort; + +/** + * An {@link IClientInfoPort} that always returns a fixed, test-controlled + * caller identity, instead of resolving one from Spring Security or the + * current HTTP request. + * + *

A test asserting on {@link com.fayupable.logged.core.model.MethodInvocationEvent#callerIdentity()} + * would otherwise need a real authenticated {@code SecurityContext} or a + * mock HTTP request just to control this one field. This class lets the + * caller identity be set directly instead. + */ +public final class InMemoryClientInfoPort implements IClientInfoPort { + + private static final String DEFAULT_CALLER_IDENTITY = "unknown"; + + private volatile String callerIdentity; + + /** + * Creates an instance that reports the caller identity as + * {@code "unknown"} until {@link #setCallerIdentity(String)} is called. + */ + public InMemoryClientInfoPort() { + this(DEFAULT_CALLER_IDENTITY); + } + + /** + * Creates an instance that reports the given caller identity. + * + * @param callerIdentity the caller identity to report + */ + public InMemoryClientInfoPort(String callerIdentity) { + this.callerIdentity = callerIdentity; + } + + @Override + public String resolveCallerIdentity() { + return callerIdentity; + } + + /** + * Changes the caller identity reported by subsequent calls to + * {@link #resolveCallerIdentity()}. + * + * @param callerIdentity the caller identity to report from now on + */ + public void setCallerIdentity(String callerIdentity) { + this.callerIdentity = callerIdentity; + } +} diff --git a/logged-test/src/main/java/com/fayupable/logged/test/InMemoryInvocationEventEmitter.java b/logged-test/src/main/java/com/fayupable/logged/test/InMemoryInvocationEventEmitter.java new file mode 100644 index 0000000..04bd577 --- /dev/null +++ b/logged-test/src/main/java/com/fayupable/logged/test/InMemoryInvocationEventEmitter.java @@ -0,0 +1,71 @@ +package com.fayupable.logged.test; + +import com.fayupable.logged.core.model.MethodInvocationEvent; +import com.fayupable.logged.core.port.InvocationEventEmitter; + +import java.util.List; +import java.util.concurrent.CopyOnWriteArrayList; + +/** + * An {@link InvocationEventEmitter} that records every event it receives in + * memory instead of publishing it anywhere, so a test can assert on what + * {@code @Logged} actually observed about a call. + * + *

Registering this as the {@code InvocationEventEmitter} bean (or passing + * it directly to a framework-free {@code LoggedAspect}) turns the emission + * side effect into something a test can inspect synchronously, without + * capturing log output or standing up a real sink. + * + *

Backed by a {@link CopyOnWriteArrayList} because a {@code @Logged} + * method under test may itself dispatch work to another thread (for example + * through {@code FlowContextPropagatingExecutor}); emission from more than + * one thread must not corrupt the recorded list or lose an event. + */ +public final class InMemoryInvocationEventEmitter implements InvocationEventEmitter { + + private final List events = new CopyOnWriteArrayList<>(); + + @Override + public void emit(MethodInvocationEvent event) { + events.add(event); + } + + /** + * Returns every event recorded so far, in emission order. + * + * @return an immutable snapshot of the recorded events + */ + public List events() { + return List.copyOf(events); + } + + /** + * Returns the number of events recorded so far. + * + * @return the recorded event count + */ + public int count() { + return events.size(); + } + + /** + * Returns the most recently recorded event. + * + * @return the last recorded event + * @throws IllegalStateException if no event has been recorded yet + */ + public MethodInvocationEvent lastEvent() { + if (events.isEmpty()) { + throw new IllegalStateException("No event has been recorded yet."); + } + return events.getLast(); + } + + /** + * Discards every event recorded so far, so this instance can be reused + * across test methods without leaking state between them. + */ + public void clear() { + events.clear(); + } +} diff --git a/logged-test/src/main/java/com/fayupable/logged/test/InMemoryMetricsRecorder.java b/logged-test/src/main/java/com/fayupable/logged/test/InMemoryMetricsRecorder.java new file mode 100644 index 0000000..3005d32 --- /dev/null +++ b/logged-test/src/main/java/com/fayupable/logged/test/InMemoryMetricsRecorder.java @@ -0,0 +1,70 @@ +package com.fayupable.logged.test; + +import com.fayupable.logged.core.port.MetricsRecorder; + +import java.util.List; +import java.util.concurrent.CopyOnWriteArrayList; + +/** + * A {@link MetricsRecorder} that records every call it is asked to record + * in memory as a {@link RecordedMetric}, instead of forwarding it to a real + * metrics backend such as Micrometer. + * + *

Unlike {@link InMemoryInvocationEventEmitter}, which mirrors a + * sampled, threshold-gated emission, this recorder always receives every + * invocation, matching {@link MetricsRecorder}'s own contract; a test + * asserting on metrics does not need to also configure sampling. + * + *

Backed by a {@link CopyOnWriteArrayList} for the same reason as + * {@link InMemoryInvocationEventEmitter}: recording may happen from more + * than one thread when the method under test hands work off to an + * executor. + */ +public final class InMemoryMetricsRecorder implements MetricsRecorder { + + private final List metrics = new CopyOnWriteArrayList<>(); + + @Override + public void record(String className, String methodName, long durationNanos, boolean success, String exceptionType) { + metrics.add(new RecordedMetric(className, methodName, durationNanos, success, exceptionType)); + } + + /** + * Returns every metric recorded so far, in recording order. + * + * @return an immutable snapshot of the recorded metrics + */ + public List metrics() { + return List.copyOf(metrics); + } + + /** + * Returns the number of metrics recorded so far. + * + * @return the recorded metric count + */ + public int count() { + return metrics.size(); + } + + /** + * Returns the most recently recorded metric. + * + * @return the last recorded metric + * @throws IllegalStateException if no metric has been recorded yet + */ + public RecordedMetric lastMetric() { + if (metrics.isEmpty()) { + throw new IllegalStateException("No metric has been recorded yet."); + } + return metrics.getLast(); + } + + /** + * Discards every metric recorded so far, so this instance can be reused + * across test methods without leaking state between them. + */ + public void clear() { + metrics.clear(); + } +} diff --git a/logged-test/src/main/java/com/fayupable/logged/test/RecordedMetric.java b/logged-test/src/main/java/com/fayupable/logged/test/RecordedMetric.java new file mode 100644 index 0000000..a8c7497 --- /dev/null +++ b/logged-test/src/main/java/com/fayupable/logged/test/RecordedMetric.java @@ -0,0 +1,25 @@ +package com.fayupable.logged.test; + +/** + * A single call recorded by {@link InMemoryMetricsRecorder}, mirroring the + * parameters of {@link com.fayupable.logged.core.port.MetricsRecorder#record} + * so a test can assert on exactly what was reported. + * + * @param className the simple or fully qualified name of the class + * declaring the invoked method + * @param methodName the name of the invoked method + * @param durationNanos the wall-clock duration of the invocation, in + * nanoseconds + * @param success {@code true} if the method returned normally, + * {@code false} if it threw an exception + * @param exceptionType the simple class name of the exception thrown by the + * method, or {@code null} if the call succeeded + */ +public record RecordedMetric( + String className, + String methodName, + long durationNanos, + boolean success, + String exceptionType +) { +} diff --git a/logged-test/src/test/java/com/fayupable/logged/test/InMemoryClientInfoPortTest.java b/logged-test/src/test/java/com/fayupable/logged/test/InMemoryClientInfoPortTest.java new file mode 100644 index 0000000..bc885a5 --- /dev/null +++ b/logged-test/src/test/java/com/fayupable/logged/test/InMemoryClientInfoPortTest.java @@ -0,0 +1,52 @@ +package com.fayupable.logged.test; + +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Nested; +import org.junit.jupiter.api.Test; + +import static org.assertj.core.api.Assertions.assertThat; + +@DisplayName("InMemoryClientInfoPort") +class InMemoryClientInfoPortTest { + + @Nested + @DisplayName("default construction") + class DefaultConstruction { + + @Test + @DisplayName("reports the caller as unknown") + void reportsUnknownCaller() { + InMemoryClientInfoPort clientInfoPort = new InMemoryClientInfoPort(); + + assertThat(clientInfoPort.resolveCallerIdentity()).isEqualTo("unknown"); + } + } + + @Nested + @DisplayName("construction with a fixed identity") + class ConstructionWithFixedIdentity { + + @Test + @DisplayName("reports the given caller identity") + void reportsGivenCallerIdentity() { + InMemoryClientInfoPort clientInfoPort = new InMemoryClientInfoPort("user:42"); + + assertThat(clientInfoPort.resolveCallerIdentity()).isEqualTo("user:42"); + } + } + + @Nested + @DisplayName("setCallerIdentity") + class SetCallerIdentity { + + @Test + @DisplayName("changes the identity reported by subsequent calls") + void changesReportedIdentity() { + InMemoryClientInfoPort clientInfoPort = new InMemoryClientInfoPort("user:42"); + + clientInfoPort.setCallerIdentity("user:99"); + + assertThat(clientInfoPort.resolveCallerIdentity()).isEqualTo("user:99"); + } + } +} diff --git a/logged-test/src/test/java/com/fayupable/logged/test/InMemoryInvocationEventEmitterTest.java b/logged-test/src/test/java/com/fayupable/logged/test/InMemoryInvocationEventEmitterTest.java new file mode 100644 index 0000000..7365701 --- /dev/null +++ b/logged-test/src/test/java/com/fayupable/logged/test/InMemoryInvocationEventEmitterTest.java @@ -0,0 +1,90 @@ +package com.fayupable.logged.test; + +import com.fayupable.logged.core.model.MethodInvocationEvent; +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Nested; +import org.junit.jupiter.api.Test; + +import java.time.Instant; + +import static org.assertj.core.api.Assertions.assertThat; +import static org.assertj.core.api.Assertions.assertThatIllegalStateException; + +@DisplayName("InMemoryInvocationEventEmitter") +class InMemoryInvocationEventEmitterTest { + + private static MethodInvocationEvent event(String methodName) { + return new MethodInvocationEvent( + "SomeClass", methodName, Instant.now(), 1_000_000L, true, null, null, "unknown", "trace-1", 0 + ); + } + + @Nested + @DisplayName("emit") + class Emit { + + @Test + @DisplayName("records events in emission order") + void recordsEventsInOrder() { + InMemoryInvocationEventEmitter emitter = new InMemoryInvocationEventEmitter(); + + emitter.emit(event("first")); + emitter.emit(event("second")); + + assertThat(emitter.events()) + .extracting(MethodInvocationEvent::methodName) + .containsExactly("first", "second"); + } + + @Test + @DisplayName("counts recorded events") + void countsRecordedEvents() { + InMemoryInvocationEventEmitter emitter = new InMemoryInvocationEventEmitter(); + + emitter.emit(event("first")); + emitter.emit(event("second")); + + assertThat(emitter.count()).isEqualTo(2); + } + } + + @Nested + @DisplayName("lastEvent") + class LastEvent { + + @Test + @DisplayName("returns the most recently emitted event") + void returnsMostRecentEvent() { + InMemoryInvocationEventEmitter emitter = new InMemoryInvocationEventEmitter(); + + emitter.emit(event("first")); + emitter.emit(event("second")); + + assertThat(emitter.lastEvent().methodName()).isEqualTo("second"); + } + + @Test + @DisplayName("throws when nothing has been recorded yet") + void throwsWhenEmpty() { + InMemoryInvocationEventEmitter emitter = new InMemoryInvocationEventEmitter(); + + assertThatIllegalStateException().isThrownBy(emitter::lastEvent); + } + } + + @Nested + @DisplayName("clear") + class Clear { + + @Test + @DisplayName("discards previously recorded events") + void discardsRecordedEvents() { + InMemoryInvocationEventEmitter emitter = new InMemoryInvocationEventEmitter(); + emitter.emit(event("first")); + + emitter.clear(); + + assertThat(emitter.count()).isZero(); + } + } +} diff --git a/logged-test/src/test/java/com/fayupable/logged/test/InMemoryMetricsRecorderTest.java b/logged-test/src/test/java/com/fayupable/logged/test/InMemoryMetricsRecorderTest.java new file mode 100644 index 0000000..9339798 --- /dev/null +++ b/logged-test/src/test/java/com/fayupable/logged/test/InMemoryMetricsRecorderTest.java @@ -0,0 +1,82 @@ +package com.fayupable.logged.test; + +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Nested; +import org.junit.jupiter.api.Test; + +import static org.assertj.core.api.Assertions.assertThat; +import static org.assertj.core.api.Assertions.assertThatIllegalStateException; + +@DisplayName("InMemoryMetricsRecorder") +class InMemoryMetricsRecorderTest { + + @Nested + @DisplayName("record") + class Record { + + @Test + @DisplayName("records calls in recording order") + void recordsCallsInOrder() { + InMemoryMetricsRecorder recorder = new InMemoryMetricsRecorder(); + + recorder.record("SomeClass", "first", 1_000_000L, true, null); + recorder.record("SomeClass", "second", 2_000_000L, false, "IllegalStateException"); + + assertThat(recorder.metrics()) + .extracting(RecordedMetric::methodName) + .containsExactly("first", "second"); + } + + @Test + @DisplayName("counts recorded calls") + void countsRecordedCalls() { + InMemoryMetricsRecorder recorder = new InMemoryMetricsRecorder(); + + recorder.record("SomeClass", "first", 1_000_000L, true, null); + recorder.record("SomeClass", "second", 2_000_000L, true, null); + + assertThat(recorder.count()).isEqualTo(2); + } + + @Test + @DisplayName("preserves every reported field") + void preservesReportedFields() { + InMemoryMetricsRecorder recorder = new InMemoryMetricsRecorder(); + + recorder.record("SomeClass", "someMethod", 1_500_000L, false, "IllegalStateException"); + + assertThat(recorder.lastMetric()).isEqualTo( + new RecordedMetric("SomeClass", "someMethod", 1_500_000L, false, "IllegalStateException") + ); + } + } + + @Nested + @DisplayName("lastMetric") + class LastMetric { + + @Test + @DisplayName("throws when nothing has been recorded yet") + void throwsWhenEmpty() { + InMemoryMetricsRecorder recorder = new InMemoryMetricsRecorder(); + + assertThatIllegalStateException().isThrownBy(recorder::lastMetric); + } + } + + @Nested + @DisplayName("clear") + class Clear { + + @Test + @DisplayName("discards previously recorded calls") + void discardsRecordedCalls() { + InMemoryMetricsRecorder recorder = new InMemoryMetricsRecorder(); + recorder.record("SomeClass", "someMethod", 1_000_000L, true, null); + + recorder.clear(); + + assertThat(recorder.count()).isZero(); + } + } +} diff --git a/pom.xml b/pom.xml index ffc4a19..3b063df 100644 --- a/pom.xml +++ b/pom.xml @@ -6,7 +6,7 @@ com.fayupable logged-lib - 1.1.0 + 1.2.0 pom logged-lib @@ -15,6 +15,7 @@ logged-core logged-spring + logged-test logged-benchmarks