From c1cadf51b0aaf205eda20fe4f9e6dbb89f1a4de4 Mon Sep 17 00:00:00 2001 From: Fayupable <90789180+Fayupable@users.noreply.github.com> Date: Mon, 3 Aug 2026 20:20:59 +0300 Subject: [PATCH] Release 1.1.0: async/thread propagation, MDC, cross-service tracing over Kafka/RabbitMQ/HTTP - Add FlowContextPropagatingExecutor / FlowContextTaskDecorator for call-chain propagation across thread hand-offs, including virtual threads and @Async - Detect CompletableFuture return types and record duration/outcome on completion instead of submission - Add MDC structured logging (LoggedMdcKeys, MdcPropagation, MdcContextPropagation) - Add RequestAttributes/SecurityContext propagating executors and task decorators for caller-identity continuity across thread hand-offs - Add cross-service trace propagation over Kafka and RabbitMQ headers (KafkaTraceHeaderCarrier, RabbitTraceHeaderCarrier) via a new public FlowContextCarrier facade - Add cross-service trace propagation over HTTP (RestTemplate, Feign, WebClient, inbound servlet filter) via HttpTraceHeaderCarrier - Reject @Logged methods returning a reactive Publisher at startup instead of silently mismeasuring an unsubscribed pipeline - Validate incoming trace ids against this library's own format across all three carriers (HTTP/Kafka/RabbitMQ) to close a log-forgery/CRLF injection vector; document the remaining, unavoidable trust-boundary risk (a well-formed but spoofed trace id) in the README - Fix className resolution to report the concrete target class instead of the proxied interface; cache class/method name resolution per invocation site - Fix LoggedAspect to restore MDC and close the flow scope from a single finally block, so an Error from a collaborator no longer skips cleanup - Fix LoggedTargetGuardBeanPostProcessor to walk the superclass chain when checking for @Logged methods - Fix LazyMetricsRecorder to stop permanently caching a "no MeterRegistry" outcome - Clamp EmissionPolicy sample rate to [0.0, 1.0] Bumps version to 1.1.0. --- CHANGELOG.md | 29 +- README.md | 262 ++++++++++- logged-benchmarks/dependency-reduced-pom.xml | 2 +- logged-benchmarks/pom.xml | 2 +- logged-core/pom.xml | 2 +- .../core/model/MethodInvocationEvent.java | 15 + .../logged/core/port/NoOpAdaptersTest.java | 2 +- logged-spring/pom.xml | 27 +- .../logged/spring/aspect/EmissionPolicy.java | 25 +- .../spring/aspect/FlowContextCarrier.java | 54 +++ .../spring/aspect/FlowContextHolder.java | 61 +++ .../FlowContextPropagatingExecutor.java | 102 +++++ .../aspect/FlowContextTaskDecorator.java | 79 ++++ .../logged/spring/aspect/LoggedAspect.java | 329 +++++++++++++- .../logged/spring/aspect/LoggedMdcKeys.java | 53 +++ .../spring/aspect/MdcContextPropagation.java | 67 +++ .../logged/spring/aspect/MdcPropagation.java | 66 +++ .../config/LoggedAutoConfiguration.java | 5 +- .../spring/config/LoggedProperties.java | 29 ++ .../emitter/Slf4jInvocationEventEmitter.java | 14 +- .../LoggedTargetGuardBeanPostProcessor.java | 94 +++- .../http/FeignTraceRequestInterceptor.java | 42 ++ ...HttpTraceClientHttpRequestInterceptor.java | 51 +++ .../http/HttpTraceExchangeFilterFunction.java | 63 +++ .../spring/http/HttpTraceHeaderCarrier.java | 156 +++++++ .../spring/http/HttpTraceServletFilter.java | 96 ++++ .../spring/kafka/KafkaTraceHeaderCarrier.java | 133 ++++++ .../spring/metrics/LazyMetricsRecorder.java | 31 +- .../metrics/MicrometerMetricsRecorder.java | 64 ++- .../rabbitmq/RabbitTraceHeaderCarrier.java | 121 +++++ .../RequestAttributesPropagatingExecutor.java | 74 +++ .../RequestAttributesPropagation.java | 60 +++ .../RequestAttributesTaskDecorator.java | 60 +++ .../SecurityContextPropagatingExecutor.java | 76 ++++ .../security/SecurityContextPropagation.java | 72 +++ .../SecurityContextTaskDecorator.java | 60 +++ .../spring/aspect/EmissionPolicyTest.java | 28 ++ .../spring/aspect/FlowContextCarrierTest.java | 82 ++++ .../spring/aspect/FlowContextHolderTest.java | 100 ++++ .../FlowContextPropagatingExecutorTest.java | 269 +++++++++++ .../aspect/FlowContextTaskDecoratorTest.java | 208 +++++++++ .../spring/aspect/LoggedAspectTest.java | 430 +++++++++++++++++- .../aspect/MdcContextPropagationTest.java | 94 ++++ .../spring/aspect/MdcPropagationTest.java | 86 ++++ .../Slf4jInvocationEventEmitterTest.java | 30 +- ...oggedTargetGuardBeanPostProcessorTest.java | 84 ++++ .../FeignTraceRequestInterceptorTest.java | 47 ++ ...TraceClientHttpRequestInterceptorTest.java | 84 ++++ .../HttpTraceExchangeFilterFunctionTest.java | 64 +++ .../http/HttpTraceHeaderCarrierTest.java | 144 ++++++ .../http/HttpTraceServletFilterTest.java | 117 +++++ .../kafka/KafkaTraceHeaderCarrierTest.java | 158 +++++++ .../metrics/LazyMetricsRecorderTest.java | 165 +++++++ .../MicrometerMetricsRecorderTest.java | 21 + .../RabbitTraceHeaderCarrierTest.java | 153 +++++++ .../NestedAsyncCallerIdentityDemoTest.java | 147 ++++++ ...uestAttributesPropagatingExecutorTest.java | 139 ++++++ .../RequestAttributesPropagationTest.java | 99 ++++ .../RequestAttributesTaskDecoratorTest.java | 92 ++++ ...ecurityContextPropagatingExecutorTest.java | 127 ++++++ .../SecurityContextPropagationTest.java | 89 ++++ .../SecurityContextTaskDecoratorTest.java | 92 ++++ pom.xml | 8 +- 63 files changed, 5561 insertions(+), 74 deletions(-) create mode 100644 logged-spring/src/main/java/com/fayupable/logged/spring/aspect/FlowContextCarrier.java create mode 100644 logged-spring/src/main/java/com/fayupable/logged/spring/aspect/FlowContextPropagatingExecutor.java create mode 100644 logged-spring/src/main/java/com/fayupable/logged/spring/aspect/FlowContextTaskDecorator.java create mode 100644 logged-spring/src/main/java/com/fayupable/logged/spring/aspect/LoggedMdcKeys.java create mode 100644 logged-spring/src/main/java/com/fayupable/logged/spring/aspect/MdcContextPropagation.java create mode 100644 logged-spring/src/main/java/com/fayupable/logged/spring/aspect/MdcPropagation.java create mode 100644 logged-spring/src/main/java/com/fayupable/logged/spring/http/FeignTraceRequestInterceptor.java create mode 100644 logged-spring/src/main/java/com/fayupable/logged/spring/http/HttpTraceClientHttpRequestInterceptor.java create mode 100644 logged-spring/src/main/java/com/fayupable/logged/spring/http/HttpTraceExchangeFilterFunction.java create mode 100644 logged-spring/src/main/java/com/fayupable/logged/spring/http/HttpTraceHeaderCarrier.java create mode 100644 logged-spring/src/main/java/com/fayupable/logged/spring/http/HttpTraceServletFilter.java create mode 100644 logged-spring/src/main/java/com/fayupable/logged/spring/kafka/KafkaTraceHeaderCarrier.java create mode 100644 logged-spring/src/main/java/com/fayupable/logged/spring/rabbitmq/RabbitTraceHeaderCarrier.java create mode 100644 logged-spring/src/main/java/com/fayupable/logged/spring/security/RequestAttributesPropagatingExecutor.java create mode 100644 logged-spring/src/main/java/com/fayupable/logged/spring/security/RequestAttributesPropagation.java create mode 100644 logged-spring/src/main/java/com/fayupable/logged/spring/security/RequestAttributesTaskDecorator.java create mode 100644 logged-spring/src/main/java/com/fayupable/logged/spring/security/SecurityContextPropagatingExecutor.java create mode 100644 logged-spring/src/main/java/com/fayupable/logged/spring/security/SecurityContextPropagation.java create mode 100644 logged-spring/src/main/java/com/fayupable/logged/spring/security/SecurityContextTaskDecorator.java create mode 100644 logged-spring/src/test/java/com/fayupable/logged/spring/aspect/FlowContextCarrierTest.java create mode 100644 logged-spring/src/test/java/com/fayupable/logged/spring/aspect/FlowContextPropagatingExecutorTest.java create mode 100644 logged-spring/src/test/java/com/fayupable/logged/spring/aspect/FlowContextTaskDecoratorTest.java create mode 100644 logged-spring/src/test/java/com/fayupable/logged/spring/aspect/MdcContextPropagationTest.java create mode 100644 logged-spring/src/test/java/com/fayupable/logged/spring/aspect/MdcPropagationTest.java create mode 100644 logged-spring/src/test/java/com/fayupable/logged/spring/http/FeignTraceRequestInterceptorTest.java create mode 100644 logged-spring/src/test/java/com/fayupable/logged/spring/http/HttpTraceClientHttpRequestInterceptorTest.java create mode 100644 logged-spring/src/test/java/com/fayupable/logged/spring/http/HttpTraceExchangeFilterFunctionTest.java create mode 100644 logged-spring/src/test/java/com/fayupable/logged/spring/http/HttpTraceHeaderCarrierTest.java create mode 100644 logged-spring/src/test/java/com/fayupable/logged/spring/http/HttpTraceServletFilterTest.java create mode 100644 logged-spring/src/test/java/com/fayupable/logged/spring/kafka/KafkaTraceHeaderCarrierTest.java create mode 100644 logged-spring/src/test/java/com/fayupable/logged/spring/metrics/LazyMetricsRecorderTest.java create mode 100644 logged-spring/src/test/java/com/fayupable/logged/spring/rabbitmq/RabbitTraceHeaderCarrierTest.java create mode 100644 logged-spring/src/test/java/com/fayupable/logged/spring/security/NestedAsyncCallerIdentityDemoTest.java create mode 100644 logged-spring/src/test/java/com/fayupable/logged/spring/security/RequestAttributesPropagatingExecutorTest.java create mode 100644 logged-spring/src/test/java/com/fayupable/logged/spring/security/RequestAttributesPropagationTest.java create mode 100644 logged-spring/src/test/java/com/fayupable/logged/spring/security/RequestAttributesTaskDecoratorTest.java create mode 100644 logged-spring/src/test/java/com/fayupable/logged/spring/security/SecurityContextPropagatingExecutorTest.java create mode 100644 logged-spring/src/test/java/com/fayupable/logged/spring/security/SecurityContextPropagationTest.java create mode 100644 logged-spring/src/test/java/com/fayupable/logged/spring/security/SecurityContextTaskDecoratorTest.java diff --git a/CHANGELOG.md b/CHANGELOG.md index 26df498..05f4737 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -6,7 +6,31 @@ The format follows [Keep a Changelog](https://keepachangelog.com/en/1.1.0/), and ## [Unreleased] -## [1.0.0] - TBD +## [1.1.0] - 2026-08-03 + +### Added + +- Async and virtual thread support: `FlowContextPropagatingExecutor` (wraps any `Executor`, including `Executors.newVirtualThreadPerTaskExecutor()`) and `FlowContextTaskDecorator` (Spring `@Async`/`TaskExecutor` integration) carry a call chain's `FlowContext` across a thread hand-off, which a `ThreadLocal`-backed context does not do on its own. +- `LoggedAspect` now detects a `@Logged` method returning `CompletableFuture` and records duration/outcome when the future actually completes (`whenComplete`), instead of at submission time; `CompletionException` wrapping from a chained stage (`thenApply`, etc.) is unwrapped to report the real exception type. +- MDC structured logging: `LoggedMdcKeys` (`logged.traceId`, `logged.depth`, `logged.className`, `logged.methodName`) are written to the current thread's MDC for the duration of a `@Logged` call, so an application's own log statements made from inside that call automatically carry the same fields in a structured logging backend (Loki, ELK) — not only this library's own summary line. Configurable via `logged.mdc.enabled` (default `true`). `FlowContextPropagatingExecutor` and `FlowContextTaskDecorator` propagate the full MDC context map across a thread hand-off as well, not just this library's own keys. +- `MethodInvocationEvent` gains `rootCauseType`, resolved by walking `Throwable#getCause()` to the deepest cause, surfacing the original failure type when a framework wraps it in a generic exception. +- `RequestAttributesPropagatingExecutor`/`RequestAttributesTaskDecorator` and `SecurityContextPropagatingExecutor`/`SecurityContextTaskDecorator`: carry the current Spring Web HTTP request and the authenticated Spring Security user, respectively, across a thread hand-off. Without these, a nested `@Logged` call made from inside work wrapped only by `FlowContextPropagatingExecutor`/`FlowContextTaskDecorator` correctly keeps its trace id and depth but silently loses caller identity on the executor thread. Both are opt-in and composable by nesting around the same delegate executor, independently of `FlowContextPropagatingExecutor`/`FlowContextTaskDecorator`. +- Cross-service tracing: `KafkaTraceHeaderCarrier` and `RabbitTraceHeaderCarrier` write the current call chain's `traceId`/depth into a Kafka or RabbitMQ message's headers when publishing, and read them back to adopt the same chain when consuming, so a `traceId` now correlates log output across service boundaries connected by a message queue, not only within a single JVM. Both depend only on `org.apache.kafka:kafka-clients`' `Headers` interface and Spring AMQP's `MessageProperties` (both `provided` scope in `logged-spring`), are opt-in like every other propagation class in this library, and never touch the message's own payload/schema. `FlowContextCarrier` (`com.fayupable.logged.spring.aspect`) is the new, narrow public entry point these two build on to read/write the active `FlowContext` from outside the `aspect` package, without exposing the rest of the package-private `FlowContextHolder`. +- `LoggedTargetGuardBeanPostProcessor` now also rejects a `@Logged` method returning a reactive `org.reactivestreams.Publisher` (Project Reactor's `Mono`/`Flux`, or an RxJava adapter implementing the same interface), failing application startup with a clear message instead of silently recording a near-zero duration and unconditional success for a pipeline that has only been assembled, not executed, by the time `@Logged` could record anything. Detected via reflection against the interface name only, so this adds no dependency on Reactor/RxJava/reactive-streams to `logged-spring`. +- Cross-service tracing over HTTP: `HttpTraceClientHttpRequestInterceptor` (`RestTemplate`), `FeignTraceRequestInterceptor` (Feign), `HttpTraceExchangeFilterFunction` (`WebClient`), and `HttpTraceServletFilter` (inbound) carry the current call chain's `traceId`/depth across a synchronous HTTP call, under `X-Logged-Trace-Id`/`X-Logged-Depth` headers, completing the cross-service tracing story alongside Kafka/RabbitMQ. All four are opt-in and built on a new, lower-level public `HttpTraceHeaderCarrier`, which operates on plain method references (`BiConsumer`/`Function`) rather than one concrete header type, so any HTTP client — not only the four integrated here — can participate by pointing it at that client's own header-writing/reading methods. `HttpTraceExchangeFilterFunction`'s Javadoc documents a caveat specific to `WebClient`'s reactive nature: it captures whichever thread's `FlowContext` is active when the request is actually subscribed to, which is not guaranteed to be the calling thread's if the request is composed with `subscribeOn`/`publishOn`. +- `HttpTraceHeaderCarrier`, `KafkaTraceHeaderCarrier`, and `RabbitTraceHeaderCarrier` now validate an incoming trace id against the exact shape this library itself ever produces (a short hexadecimal string) before adopting it, rejecting anything else exactly like a missing header. This closes a log-forgery vector specific to the HTTP carrier: without it, an untrusted caller of a publicly reachable endpoint could set `X-Logged-Trace-Id` to a value containing control characters (for example a newline) crafted to inject a fabricated line into log output. This does not, and cannot, verify that a well-formed trace id actually originated from a trusted caller — see the "trusting the incoming `X-Logged-Trace-Id` header" note in the README for the residual, unavoidable trust boundary this leaves. + +### Changed + +- `LoggedAspect` now resolves the reported class name from `ProceedingJoinPoint#getTarget()` instead of the join point signature, so it reports the concrete implementing class rather than the interface `@Logged` is declared on. +- Class and method name resolution is now cached per `(target class, method)` pair, avoiding repeated reflection on every invocation of the same method. +- `MicrometerMetricsRecorder`'s internal meter caches now key on dedicated records (`InvocationCounterKey`, `DurationTimerKey`, `ErrorCounterKey`) instead of concatenated strings, removing a theoretical cache-key collision when `className` is a fully qualified name. +- `LoggedAspect.logInvocation` now restores the MDC and closes the flow scope from a single `finally` block instead of duplicating that pair of calls at three call sites, so it also runs if a collaborator (`MetricsRecorder`/`InvocationEventEmitter`) throws an `Error` rather than a `RuntimeException`. +- `LoggedTargetGuardBeanPostProcessor` now walks a bean's superclass chain when checking for a `@Logged` method, instead of only its declared methods, so a `@Logged` method inherited from an abstract base class can no longer bypass the guard on a disallowed subclass. +- `LazyMetricsRecorder` no longer permanently caches a "no `MeterRegistry` available" outcome; it retries on every call until a registry is found, instead of staying pinned to a no-op recorder for the application's lifetime if the very first `@Logged` invocation raced ahead of the registry bean's creation. +- `EmissionPolicy` now clamps `Logged#sampleRate()` to `[0.0, 1.0]` before using it, making out-of-range values (`> 1.0` or `< 0.0`) behave as an explicit, defined "always"/"never" instead of relying on `ThreadLocalRandom`'s specific range. + +## [1.0.0] - 2026-07-24 ### Added @@ -24,5 +48,6 @@ 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.0.0...HEAD +[Unreleased]: https://github.com/fayupable/logged-lib/compare/v1.1.0...HEAD +[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 0c6bdc1..e4b5119 100644 --- a/README.md +++ b/README.md @@ -31,6 +31,10 @@ public class OrderService { - [Quick start](#quick-start) - [What `@Logged` captures — and what it never does](#what-logged-captures--and-what-it-never-does) - [Call chain tracking](#call-chain-tracking) +- [Async, `@Async`, and virtual thread support](#async-async-and-virtual-thread-support) +- [Structured logging (MDC)](#structured-logging-mdc) +- [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) - [Configuration](#configuration) - [Modules](#modules) @@ -120,6 +124,247 @@ When a `@Logged` method calls another `@Logged` method — directly, or through If a failure happens partway through a chain, the failing call and every call above it in the chain are marked as failed with the same `traceId`; calls that would have happened deeper in the chain simply never appear, since the chain stopped there. The deepest `FAILED` entry for a given `traceId` is exactly where the chain broke. +## Async, `@Async`, and virtual thread support + +Call chain tracking, described above, is implemented with a `ThreadLocal`. That is a deliberate, cheap choice — but it means the tracked context only exists on the thread that set it. **The moment a `@Logged` method hands its work off to a different thread, that context does not follow automatically.** Without one of the fixes below, a `@Logged` call made from inside a `@Async` method, a manually submitted `Runnable`/`Callable`, or a `CompletableFuture`'s async stage starts a brand-new, disconnected chain: a new `traceId`, `depth` reset to zero, and no way to tell from the log output that it was ever related to the call that triggered it. + +This is not specific to platform threads or thread pools in the traditional sense — it applies exactly the same way to `Executors.newVirtualThreadPerTaskExecutor()`. A virtual thread is still a distinct thread with its own `ThreadLocal` storage; nothing about virtual threads changes this problem or solves it on its own. + +The fix is the same idea in every case: capture the context on the thread handing off the work, and restore it on the thread that actually runs it. This library ships two ready-made ways to do that, and one `CompletableFuture` behavior that requires no wiring at all. + +### Wrapping your own `Executor` + +If you submit work to an `Executor` or `ExecutorService` you manage directly — including a virtual-thread-per-task executor — wrap it once with `FlowContextPropagatingExecutor`: + +```java +Executor virtualThreadExecutor = Executors.newVirtualThreadPerTaskExecutor(); +Executor propagating = new FlowContextPropagatingExecutor(virtualThreadExecutor); + +@Logged +public void processOrder(Order order) { + propagating.execute(() -> { + // Any @Logged call made in here is recognized as part of the + // caller's chain, at the caller's depth — not a new chain. + auditLogService.record(order); + }); +} +``` + +Every task submitted through the wrapped executor carries whatever context was active on the submitting thread at the moment `execute(...)` was called, and the executor thread's own state is always restored afterward — including when the submitted task throws. + +### Wiring up Spring's `@Async` + +`@Async` methods are dispatched by Spring's own `TaskExecutor` machinery, which your code never touches directly, so wrapping an `Executor` yourself does not apply here. Spring provides exactly the extension point this library needs — `TaskDecorator` — and this library ships an implementation of it: + +```java +@Bean +public TaskExecutor taskExecutor() { + ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor(); + executor.setTaskDecorator(new FlowContextTaskDecorator()); + executor.initialize(); + return executor; +} +``` + +Once this is registered, every `@Async` method dispatched through that executor carries the calling thread's chain forward. **This is not wired up automatically for every `TaskExecutor` bean in your application** — auto-attaching to any executor found in the application context would silently change the behavior of executors this library was never meant to touch. You decide which executor `@Logged` call chains should survive across, the same way you decide which methods get `@Logged` in the first place. + +### `CompletableFuture` + +A `@Logged` method that returns a `CompletableFuture` is detected and handled correctly **without any extra wiring**: this library measures the duration and outcome when the future actually completes, not when it is merely constructed and returned, so a method like this reports its real asynchronous duration and the real success/failure of the async work, not just how long it took to submit: + +```java +@Logged(slowThresholdMs = 500, sampleRate = 1.0) +public CompletableFuture processOrderAsync(Order order) { + return CompletableFuture.supplyAsync(() -> doWork(order), executor); +} +``` + +This part requires nothing from you. What still requires the wiring described above is whether a **nested** `@Logged` call made *inside* that async stage is recognized as part of the same chain — that depends on whatever `Executor` the async stage itself runs on: + +- `CompletableFuture.supplyAsync(supplier, propagatingExecutor)` — pass a `FlowContextPropagatingExecutor` explicitly, and any `@Logged` call inside `supplier` joins the caller's chain. +- `CompletableFuture.supplyAsync(supplier)` (no executor argument) — runs on the shared, JVM-wide `ForkJoinPool.commonPool()`. This library will never wrap that pool automatically: it is shared by unrelated code throughout the JVM, and silently altering its behavior is exactly the kind of surprising, hard-to-diagnose side effect this library avoids elsewhere. If you need chain continuity here, always pass an explicit, wrapped executor instead of relying on the default. + +### Carrying the current request and authenticated user across the same boundary + +`FlowContextPropagatingExecutor` and `FlowContextTaskDecorator` only carry this library's own call-chain tracking and MDC across a thread hand-off. They deliberately do not also carry Spring Web's current HTTP request or Spring Security's authenticated user, so that they stay usable in applications that have neither on their classpath at all. + +Without anything further, a **nested** `@Logged` call made from inside async work loses caller identity entirely on the executor thread: [caller resolution](#caller-resolution) falls back to an IP address, or `"unknown"`, even though the call's trace id and depth still propagate correctly. Two additional, equally optional decorators close this gap, one per concern: + +| Decorator | Carries | Needs | +|---|---|---| +| `RequestAttributesPropagatingExecutor` / `RequestAttributesTaskDecorator` | The current HTTP request (`RequestContextHolder`) | Spring Web | +| `SecurityContextPropagatingExecutor` / `SecurityContextTaskDecorator` | The authenticated user (`SecurityContextHolder`) | Spring Security | + +Nest whichever ones you need around the same delegate — order does not matter, since each one manages an independent `ThreadLocal`: + +```java +Executor fullyPropagating = new FlowContextPropagatingExecutor( + new SecurityContextPropagatingExecutor( + new RequestAttributesPropagatingExecutor(realExecutor))); +``` + +For `@Async`, since `ThreadPoolTaskExecutor` only accepts a single `TaskDecorator`, compose them by nesting `decorate()` calls instead: + +```java +@Bean +public TaskExecutor taskExecutor() { + ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor(); + executor.setTaskDecorator(runnable -> + new FlowContextTaskDecorator().decorate( + new SecurityContextTaskDecorator().decorate( + new RequestAttributesTaskDecorator().decorate(runnable)))); + executor.initialize(); + return executor; +} +``` + +This is a one-time setup step, written once wherever you define the executor bean — not something repeated at every call site. + +## Structured logging (MDC) + +While a `@Logged` method runs, this library writes four keys into the current thread's SLF4J [MDC](https://www.slf4j.org/api/org/slf4j/MDC.html): + +| Key | Value | +|---|---| +| `logged.traceId` | the call chain's trace id (see [Call chain tracking](#call-chain-tracking)) | +| `logged.depth` | the current call's depth within its chain | +| `logged.className` | the class name resolved for the current invocation | +| `logged.methodName` | the method name resolved for the current invocation | + +This is separate from, and in addition to, the summary line this library's own `InvocationEventEmitter` produces. Its real value is that **your own log statements**, written from inside a `@Logged` method, automatically pick up these fields too — without threading any of this information through by hand: + +```java +@Logged(slowThresholdMs = 500, sampleRate = 1.0) +public void placeOrder(Long userId, Long productId) { + log.info("Stock check started"); // your own, ordinary log statement + checkStock(productId); + log.info("Payment charged"); // your own, ordinary log statement + chargePayment(userId); +} +``` + +With a Logback pattern (or JSON encoder) that includes the MDC, every one of those lines — not just this library's own summary — carries the same `logged.traceId`: + +```xml +%d{HH:mm:ss.SSS} %-5level %logger{36} - %msg [traceId=%X{logged.traceId}]%n +``` + +``` +10:00:01.001 INFO OrderService - Stock check started [traceId=fd6a56d153407322] +10:00:01.045 INFO OrderService - Payment charged [traceId=fd6a56d153407322] +10:00:01.052 INFO Slf4jInvocationEventEmitter - [user:42] OrderService.placeOrder completed in 187ms [traceId=fd6a56d153407322] +``` + +In Grafana/Loki, filtering on `{logged_traceId="fd6a56d153407322"}` now returns every line involved in that single call — your own business logs and this library's summary line together, in order — instead of only the one line this library emits itself. + +Keys are prefixed with `logged.` specifically to avoid colliding with an MDC key your application, or another library, already uses (a bare `traceId` key is common enough that a collision is likely without this prefix). + +This can be disabled entirely, if you manage MDC yourself or want to avoid the extra `MDC.put`/`MDC.remove` calls on a very hot path: + +```yaml +logged: + mdc: + enabled: false +``` + +`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. + +## 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. + +`KafkaTraceHeaderCarrier` and `RabbitTraceHeaderCarrier` close that gap by writing the current `traceId`/depth into the message's **headers** — never into its body — when publishing, and reading them back when consuming: + +```java +// Producing (Kafka) +ProducerRecord record = new ProducerRecord<>("orders", event); +KafkaTraceHeaderCarrier.writeToHeaders(record.headers()); +kafkaTemplate.send(record); +``` + +```java +// Consuming (Kafka) +@KafkaListener(topics = "orders") +public void onOrderPlaced(ConsumerRecord record) { + KafkaTraceHeaderCarrier.readAndAdopt(record.headers(), () -> + inventoryService.reserveStock(record.value())); +} +``` + +```java +// Publishing (RabbitMQ) +MessageProperties properties = new MessageProperties(); +RabbitTraceHeaderCarrier.writeToHeaders(properties); +rabbitTemplate.send(exchange, routingKey, new Message(body, properties)); +``` + +```java +// Consuming (RabbitMQ) +@RabbitListener(queues = "notifications") +public void onNotificationRequested(Message message) { + RabbitTraceHeaderCarrier.readAndAdopt(message.getMessageProperties(), () -> + notificationService.sendPushNotification(message)); +} +``` + +The message's payload — its schema, its serialization format (JSON, Avro, protobuf, or anything else) — is never touched. If a message carries no trace headers (published by a service that does not use this library, for example), `readAndAdopt` simply runs the given work as-is; any `@Logged` call inside it then starts a new chain of its own, exactly as if this class were not involved at all. + +Both are optional and depend only on `org.apache.kafka:kafka-clients`' `Headers` interface and Spring AMQP's `MessageProperties`, respectively — not `spring-kafka` specifically, so this works whether you produce/consume with `KafkaTemplate`/`@KafkaListener` or a plain `KafkaProducer`/`KafkaConsumer`. Both dependencies are `provided` scope in `logged-spring`: they are needed to compile this library, but are never forced onto a consuming application's own dependency tree, and neither `KafkaTraceHeaderCarrier` nor `RabbitTraceHeaderCarrier` is wired in automatically anywhere — call them explicitly, exactly where you already publish or consume a message. + +**What crosses the queue, and what does not.** Only the call chain's `traceId` and `depth` cross a Kafka or RabbitMQ message — not the full MDC context map, and not the authenticated caller. This is a deliberate scope boundary, not an oversight: [MDC propagation](#structured-logging-mdc) and [caller identity propagation](#async-async-and-virtual-thread-support) both exist to carry state across a boundary that is still logically the *same* request (a thread hand-off within one service). A message consumed from a queue is a fundamentally different kind of boundary — it starts a new unit of work, generally with no single authenticated "caller" of its own, so `@Logged` methods on the consuming side resolve their own caller identity independently (typically `"unknown"`, since a queue consumer thread has no HTTP request or Spring Security context unless your own listener code establishes one). The `traceId` still lets you correlate that consumer-side log output with the producing service's, even though the two sides may report different caller identities. + +## Cross-service tracing over HTTP + +The synchronous counterpart to Kafka/RabbitMQ propagation: when one service calls another directly over HTTP (a Feign client, `RestTemplate`, or `WebClient`), the `traceId` crosses in the request's headers, under `X-Logged-Trace-Id`/`X-Logged-Depth` — never in the request body. + +**Outbound** — pick whichever client you use: + +```java +// RestTemplate +restTemplate.getInterceptors().add(new HttpTraceClientHttpRequestInterceptor()); +``` + +```java +// Feign — Spring Cloud OpenFeign auto-detects any RequestInterceptor bean +@Bean +public RequestInterceptor loggedTraceRequestInterceptor() { + return new FeignTraceRequestInterceptor(); +} +``` + +```java +// WebClient +WebClient webClient = WebClient.builder() + .filter(new HttpTraceExchangeFilterFunction()) + .build(); +``` + +**Inbound** — the receiving service reads the same headers back, so its own `@Logged` calls join the caller's chain instead of starting a new one: + +```java +@Bean +public FilterRegistrationBean httpTraceServletFilter() { + FilterRegistrationBean registration = + new FilterRegistrationBean<>(new HttpTraceServletFilter()); + registration.setOrder(Ordered.HIGHEST_PRECEDENCE); + return registration; +} +``` + +All four are opt-in, exactly like every other propagation class in this library — none is wired in automatically. `RestTemplate` and Feign are purely synchronous, so there is no ambiguity about which thread's context is captured; it is always the calling thread's. + +**`WebClient` has one caveat worth knowing.** It is reactive: `HttpTraceExchangeFilterFunction` runs whenever the request is actually subscribed to, which — if composed with `subscribeOn`/`publishOn` — may not be the same thread that built the call in your code. For the common case of a `@Logged` method calling `WebClient` and blocking on the result (`.block()`), the subscribing thread and the calling thread are the same, and this behaves exactly like `RestTemplate`/Feign. Full correctness across an arbitrarily composed reactive chain would require bridging `FlowContext` through Reactor's own `Context`, which this library does not do (see [Where `@Logged` belongs](#where-logged-belongs) for the related `Mono`/`Flux` return type limitation). + +**A note on trusting the incoming `X-Logged-Trace-Id` header.** `HttpTraceHeaderCarrier.readAndAdopt` only accepts a value shaped like a trace id this library could actually have produced itself (a short hexadecimal string); anything else — including an attempt to inject control characters to forge fake log lines — is rejected outright and treated as no header at all. What this validation does **not** do is verify that the value actually originated from one of your own services: a well-formed but fabricated `X-Logged-Trace-Id` (for example `aabbccdd11223344`) still passes it, exactly the way a forged `X-Forwarded-For` value would. This cannot be closed without a fundamentally heavier mechanism (cryptographically signing the trace id), which would be disproportionate for what is meant to be a lightweight correlation id, not a security token — the trace id is never evaluated, executed, or used for any authorization decision, so the worst a fabricated value can do is make a caller's own log output appear correlated under a trace id it does not legitimately belong to (a data-integrity concern for your own observability, not a code-execution or data-exposure one). If `HttpTraceServletFilter` is registered on an endpoint directly reachable by untrusted external callers, treat the incoming trace id the same way this library already treats `X-Forwarded-For`: as caller-supplied, not authenticated. Only register it where the caller is another of your own services (Feign/`RestTemplate`/`WebClient` calls from within your own application boundary), or strip/validate this header at your gateway for traffic you do not trust. + +**Using a different HTTP client entirely?** All four classes above are thin wrappers around a lower-level, public `HttpTraceHeaderCarrier`, which operates on plain method references rather than one specific header type, so it works with any client that exposes a `(name, value) -> void` header-writing method and a `(name) -> String` header-reading method: + +```java +// Any HTTP client with its own header API +HttpTraceHeaderCarrier.writeToHeaders(connection::setRequestProperty); +HttpTraceHeaderCarrier.readAndAdopt(connection::getHeaderField, () -> handleRequest()); +``` + ## Where `@Logged` belongs `@Logged` is meant for **service and application-layer methods**, and for **adapters calling external systems** (a Feign client checking stock before an order is placed, for example), where knowing that an operation ran, how long it took, and whether it failed is operationally useful. @@ -135,6 +380,18 @@ to the service or application layer method that calls this bean instead. This is deliberate: entities can be invoked at a frequency (JSON serialization, JPA dirty checking) that would drown out everything else, and repositories are already covered by lower-level persistence metrics. +**`@Logged` also cannot be applied to a method returning a reactive `Publisher`** (Project Reactor's `Mono`/`Flux`, or an RxJava adapter implementing the same interface) — the same startup guard rejects this too: + +``` +IllegalStateException: @Logged is not supported on method com.example.OrderService#placeOrder +(bean 'orderService'): it returns reactor.core.publisher.Mono, a reactive publisher. Recording +would measure only how long the pipeline took to assemble, not the actual asynchronous work, +and would always report success even if the pipeline later fails. Use CompletableFuture instead, +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. + ## Configuration Every property below is optional and defaults to preserving the library's out-of-the-box behavior unmodified. @@ -144,6 +401,7 @@ Every property below is optional and defaults to preserving the library's out-of | `logged.enabled` | `true` | Global switch. Setting this to `false` removes the aspect entirely; `@Logged` methods run uninstrumented. | | `logged.metrics.enabled` | `true` | Setting this to `false` falls back to a no-op metrics recorder even when a `MeterRegistry` bean is present. | | `logged.client-info.trust-forwarded-headers` | `false` | Whether the caller-IP resolver may trust the client-controlled `X-Forwarded-For` header. Only enable this after confirming the application sits behind a proxy that strips and re-sets this header itself — see [Caller resolution](#caller-resolution). | +| `logged.mdc.enabled` | `true` | Whether `logged.traceId`/`logged.depth`/`logged.className`/`logged.methodName` are written to the current thread's MDC during a `@Logged` call — see [Structured logging (MDC)](#structured-logging-mdc). | ```yaml logged: @@ -160,7 +418,7 @@ logged: | `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, and full auto-configuration. Every Spring/Micrometer/Security 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 or Spring Security, the corresponding feature simply falls back to a no-op. +- **`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-benchmarks`** never leaves this repository; see [Benchmarks](#benchmarks). ## Metrics @@ -217,7 +475,7 @@ Results will vary by hardware and JVM. The benchmark class lives at `logged-benc Every module is covered by real, behavior-driven tests — Spring AOP proxies exercised through `AspectJProxyFactory`, real `ApplicationContextRunner` contexts for auto-configuration, real `SimpleMeterRegistry` and Logback `ListAppender` instances for metrics and log output, never mocks standing in for the thing actually being verified. -- **Tests**: 77 across both modules, `mvn test`. +- **Tests**: 209 across both modules, `mvn test`. - **Mutation testing** ([Pitest](https://pitest.org/)): `logged-core` at 100%, `logged-spring` at 98%, enforced via `mvn verify`. - **Style** ([Checkstyle](https://checkstyle.org/)): 0 violations, a small rule set (unused/star imports, missing braces, unreachable line lengths) chosen to catch real mistakes without dictating subjective formatting. diff --git a/logged-benchmarks/dependency-reduced-pom.xml b/logged-benchmarks/dependency-reduced-pom.xml index e22b3fc..8d5b8ba 100644 --- a/logged-benchmarks/dependency-reduced-pom.xml +++ b/logged-benchmarks/dependency-reduced-pom.xml @@ -3,7 +3,7 @@ logged-lib com.fayupable - 1.0.0-SNAPSHOT + 1.1.0 4.0.0 logged-benchmarks diff --git a/logged-benchmarks/pom.xml b/logged-benchmarks/pom.xml index 74e35e5..d944963 100644 --- a/logged-benchmarks/pom.xml +++ b/logged-benchmarks/pom.xml @@ -7,7 +7,7 @@ com.fayupable logged-lib - 1.0.0 + 1.1.0 logged-benchmarks diff --git a/logged-core/pom.xml b/logged-core/pom.xml index ed93d35..087b8a7 100644 --- a/logged-core/pom.xml +++ b/logged-core/pom.xml @@ -7,7 +7,7 @@ com.fayupable logged-lib - 1.0.0 + 1.1.0 logged-core diff --git a/logged-core/src/main/java/com/fayupable/logged/core/model/MethodInvocationEvent.java b/logged-core/src/main/java/com/fayupable/logged/core/model/MethodInvocationEvent.java index 71e1e1a..ac9b109 100644 --- a/logged-core/src/main/java/com/fayupable/logged/core/model/MethodInvocationEvent.java +++ b/logged-core/src/main/java/com/fayupable/logged/core/model/MethodInvocationEvent.java @@ -23,6 +23,20 @@ * the method, or {@code null} if the call succeeded; * the exception message is never captured here, * since it may contain sensitive data + * @param rootCauseType the simple class name of the deepest + * {@link Throwable#getCause()} in the chain started + * by the exception described by + * {@code exceptionType}, or {@code null} if the call + * succeeded. Equal to {@code exceptionType} itself + * when the thrown exception has no cause. Frameworks + * commonly wrap a lower-level failure (for example a + * driver-specific SQL exception) inside a generic + * exception type (for example a Spring + * {@code DataAccessException}); {@code exceptionType} + * alone would only ever show the generic wrapper, so + * this field surfaces the original failure type + * instead. As with {@code exceptionType}, only the + * class name is captured, never the message * @param callerIdentity an opaque identifier describing who triggered the * call (for example an authenticated user id or a * client IP address), resolved by an adapter-specific @@ -42,6 +56,7 @@ public record MethodInvocationEvent( long durationNanos, boolean success, String exceptionType, + String rootCauseType, String callerIdentity, String traceId, int depth diff --git a/logged-core/src/test/java/com/fayupable/logged/core/port/NoOpAdaptersTest.java b/logged-core/src/test/java/com/fayupable/logged/core/port/NoOpAdaptersTest.java index c2bd258..a5ab734 100644 --- a/logged-core/src/test/java/com/fayupable/logged/core/port/NoOpAdaptersTest.java +++ b/logged-core/src/test/java/com/fayupable/logged/core/port/NoOpAdaptersTest.java @@ -17,7 +17,7 @@ class NoOpAdaptersTest { void noOpInvocationEventEmitterDoesNotThrow() { InvocationEventEmitter emitter = new NoOpInvocationEventEmitter(); MethodInvocationEvent event = new MethodInvocationEvent( - "SomeClass", "someMethod", Instant.now(), 1_000_000L, true, null, "unknown", "trace-1", 0 + "SomeClass", "someMethod", Instant.now(), 1_000_000L, true, null, null, "unknown", "trace-1", 0 ); assertThatCode(() -> emitter.emit(event)).doesNotThrowAnyException(); diff --git a/logged-spring/pom.xml b/logged-spring/pom.xml index c8f582c..1e1e9b6 100644 --- a/logged-spring/pom.xml +++ b/logged-spring/pom.xml @@ -7,7 +7,7 @@ com.fayupable logged-lib - 1.0.0 + 1.1.0 logged-spring @@ -53,6 +53,31 @@ micrometer-core provided + + org.apache.kafka + kafka-clients + provided + + + org.springframework.amqp + spring-rabbit + provided + + + org.springframework + spring-webflux + provided + + + io.projectreactor + reactor-core + provided + + + io.github.openfeign + feign-core + provided + org.junit.jupiter diff --git a/logged-spring/src/main/java/com/fayupable/logged/spring/aspect/EmissionPolicy.java b/logged-spring/src/main/java/com/fayupable/logged/spring/aspect/EmissionPolicy.java index 2b9dd26..ff362b1 100644 --- a/logged-spring/src/main/java/com/fayupable/logged/spring/aspect/EmissionPolicy.java +++ b/logged-spring/src/main/java/com/fayupable/logged/spring/aspect/EmissionPolicy.java @@ -37,6 +37,29 @@ static boolean shouldEmit(Logged logged, long durationNanos, boolean success) { return true; } - return ThreadLocalRandom.current().nextDouble() < logged.sampleRate(); + return ThreadLocalRandom.current().nextDouble() < clampSampleRate(logged.sampleRate()); + } + + /** + * Clamps {@code sampleRate} to the documented {@code [0.0, 1.0]} range + * of {@link Logged#sampleRate()}. + * + *

{@code @Logged} annotation attributes cannot enforce a value range + * at compile time the way a method parameter could with a runtime + * assertion at the call site, so a consumer can write + * {@code @Logged(sampleRate = 2.0)} or a negative value without any + * compiler or startup-time error. Left unclamped, {@link + * ThreadLocalRandom#nextDouble()}'s {@code [0.0, 1.0)} range makes a + * value above {@code 1.0} behave as "always sample" and a negative + * value behave as "never sample" anyway, so this never causes incorrect + * behavior — but relying on that coincidence would leave the actual + * intent undefined. Clamping makes the resulting behavior explicit and + * independent of {@link ThreadLocalRandom}'s specific range. + * + * @param sampleRate the raw {@link Logged#sampleRate()} value + * @return {@code sampleRate} restricted to {@code [0.0, 1.0]} + */ + private static double clampSampleRate(double sampleRate) { + return Math.clamp(sampleRate, 0.0, 1.0); } } \ No newline at end of file diff --git a/logged-spring/src/main/java/com/fayupable/logged/spring/aspect/FlowContextCarrier.java b/logged-spring/src/main/java/com/fayupable/logged/spring/aspect/FlowContextCarrier.java new file mode 100644 index 0000000..5c01154 --- /dev/null +++ b/logged-spring/src/main/java/com/fayupable/logged/spring/aspect/FlowContextCarrier.java @@ -0,0 +1,54 @@ +package com.fayupable.logged.spring.aspect; + +import com.fayupable.logged.core.model.FlowContext; + +/** + * The sanctioned public entry point for reading and writing this thread's + * active {@link FlowContext} from outside the {@code aspect} package. + * + *

{@link FlowContextHolder} deliberately stays package-private: it is an + * internal detail of {@link LoggedAspect}, not part of this library's public + * API. But carrying a call chain across a boundary that is not a plain Java + * thread hand-off — a Kafka or RabbitMQ message, for example — requires code + * outside this package to read the current {@link FlowContext} on a + * producing thread and re-establish it on a consuming thread, in modules + * (this library's own {@code kafka}/{@code rabbitmq} packages today, a + * consuming application's own carrier tomorrow) that have no reason to see + * anything else {@link FlowContextHolder} exposes. + * + *

This class exists to be that one, narrow, intentional door: two + * methods, mirroring {@link FlowContextHolder#snapshot()} and + * {@link FlowContextHolder#adopt}, and nothing else. It does not replace + * {@link FlowContextHolder}; it is a thin, public façade in front of it, + * kept in the same package specifically so it can call it. + */ +public final class FlowContextCarrier { + + private FlowContextCarrier() { + } + + /** + * Returns the {@link FlowContext} currently active on this thread, or + * {@code null} if no {@code @Logged} call is in progress on this + * thread. + * + * @return the active flow context, or {@code null} if none is active + */ + public static FlowContext capture() { + return FlowContextHolder.snapshot(); + } + + /** + * Makes {@code context} the active {@link FlowContext} on the calling + * thread and returns a {@link Runnable} that undoes this, restoring + * whatever context was active before this call. + * + * @param context the context to make active, or {@code null} to clear + * whatever is currently active + * @return a {@link Runnable} that restores this thread's previous + * context; never {@code null} + */ + public static Runnable adopt(FlowContext context) { + return FlowContextHolder.adopt(context); + } +} diff --git a/logged-spring/src/main/java/com/fayupable/logged/spring/aspect/FlowContextHolder.java b/logged-spring/src/main/java/com/fayupable/logged/spring/aspect/FlowContextHolder.java index fa78da9..cfb6ee6 100644 --- a/logged-spring/src/main/java/com/fayupable/logged/spring/aspect/FlowContextHolder.java +++ b/logged-spring/src/main/java/com/fayupable/logged/spring/aspect/FlowContextHolder.java @@ -64,4 +64,65 @@ public void close() { } } } + + /** + * Returns the {@link FlowContext} currently active on this thread, + * without modifying it, or {@code null} if no {@code @Logged} call is + * in progress on this thread. + * + *

This is the read side of propagating a call chain across a thread + * boundary: code about to hand work off to another thread (for example + * submitting it to an {@link java.util.concurrent.Executor}) calls this + * on the submitting thread to capture what should be restored once the + * work actually runs. Because {@link FlowContext} is an immutable + * record, the returned value is safe to pass to another thread without + * any further synchronization. + * + * @return the active flow context, or {@code null} if none is active + */ + static FlowContext snapshot() { + return FLOW.get(); + } + + /** + * Makes {@code context} the active {@link FlowContext} on the calling + * thread and returns a {@link Runnable} that undoes this, restoring + * whatever context was active before this call. + * + *

This is the write side of propagating a call chain across a thread + * boundary, used together with {@link #snapshot()}: the thread that + * will actually run the handed-off work calls this with the context + * captured on the original thread, so that any nested {@code @Logged} + * call made from within that work is recognized as part of the same + * chain instead of starting a new one. Unlike {@link #enter()}, this + * does not derive a deeper context via {@link FlowContext#next()} — the + * handed-off work is a continuation of the same logical step, not a new + * one, so the depth carried by {@code context} is reused as-is. + * + *

The returned {@link Runnable} must be run once the handed-off work + * completes, typically in a {@code finally} block, so that a thread + * reused by a pool (for example between two unrelated tasks) does not + * keep leaking a stale context into whatever runs on it next. + * + * @param context the context captured by {@link #snapshot()} on the + * thread that is handing off work, or {@code null} if + * that thread had none active + * @return a {@link Runnable} that restores this thread's previous + * context; never {@code null} + */ + static Runnable adopt(FlowContext context) { + FlowContext previous = FLOW.get(); + if (context == null) { + FLOW.remove(); + } else { + FLOW.set(context); + } + return () -> { + if (previous == null) { + FLOW.remove(); + } else { + FLOW.set(previous); + } + }; + } } \ No newline at end of file diff --git a/logged-spring/src/main/java/com/fayupable/logged/spring/aspect/FlowContextPropagatingExecutor.java b/logged-spring/src/main/java/com/fayupable/logged/spring/aspect/FlowContextPropagatingExecutor.java new file mode 100644 index 0000000..2b4ada2 --- /dev/null +++ b/logged-spring/src/main/java/com/fayupable/logged/spring/aspect/FlowContextPropagatingExecutor.java @@ -0,0 +1,102 @@ +package com.fayupable.logged.spring.aspect; + +import com.fayupable.logged.core.model.FlowContext; +import org.jspecify.annotations.NonNull; + +import java.util.Map; +import java.util.Objects; +import java.util.concurrent.Executor; + +/** + * {@link Executor} decorator that carries the submitting thread's + * {@link FlowContext} and {@link org.slf4j.MDC} context over to whatever + * thread actually runs the submitted task. + * + *

{@link FlowContextHolder} tracks call-chain position through a + * {@link ThreadLocal}, which by definition only exists on the thread that + * set it. As soon as work is handed off to a different thread — a + * {@code @Async} method, a {@link java.util.concurrent.CompletableFuture} + * running on a custom {@link Executor}, a task submitted to + * {@link java.util.concurrent.Executors#newVirtualThreadPerTaskExecutor()} — + * that thread starts with no context of its own, and any {@code @Logged} + * call made from within it is reported as the start of a brand new chain + * instead of a continuation of the caller's chain. This class closes that + * gap for any {@link Executor}-based hand-off, including virtual thread + * executors: an {@link Executor} is an {@link Executor} regardless of the + * kind of thread backing it, so no separate handling is needed for virtual + * threads specifically. + * + *

Wrapping is a one-time setup step; call sites do not change: + * + * 

{@code
+ * Executor virtualThreadExecutor =
+ *         Executors.newVirtualThreadPerTaskExecutor();
+ * Executor propagating =
+ *         new FlowContextPropagatingExecutor(virtualThreadExecutor);
+ *
+ * // Inside a @Logged method:
+ * propagating.execute(() -> {
+ *     // Any @Logged call made here is recognized as part of the
+ *     // caller's chain, at the same depth the caller was at.
+ *     someOtherLoggedBean.doWork();
+ * });
+ * }
+ * + *

The context is captured once per {@link #execute(Runnable)} call, on + * the calling thread, at the moment the task is submitted — not when it + * starts running. This matters because a pooled {@link Executor} may not + * run the task immediately; capturing eagerly guarantees the propagated + * context reflects the caller's state at submission time, which is what a + * human reading the resulting call chain would expect, rather than whatever + * happened to be active on the calling thread later when the pool got + * around to it. + * + *

This class is deliberately not a Spring bean and requires no + * {@code ApplicationContext}: it only depends on {@link FlowContextHolder} + * and the {@link Executor} it wraps, so it can decorate any executor a + * consuming application already manages, including ones created outside of + * Spring's control. + */ +public final class FlowContextPropagatingExecutor implements Executor { + + private final Executor delegate; + + /** + * Wraps {@code delegate} so that every task submitted through this + * executor carries the submitting thread's {@link FlowContext} into + * whichever thread {@code delegate} actually runs it on. + * + * @param delegate the executor that will actually run submitted tasks + */ + public FlowContextPropagatingExecutor(Executor delegate) { + this.delegate = Objects.requireNonNull(delegate, "delegate must not be null"); + } + + /** + * Captures the calling thread's current {@link FlowContext} and MDC + * context map, and submits a wrapped task to the delegate executor that + * restores both before running {@code command} and restores the + * executor thread's own previous state again afterward, regardless of + * whether {@code command} completes normally or throws. + * + *

The MDC context map is captured and restored in full, not limited + * to {@link LoggedMdcKeys}: see {@link MdcContextPropagation} for why. + * + * @param command the task to run + */ + @Override + public void execute(@NonNull Runnable command) { + FlowContext capturedContext = FlowContextHolder.snapshot(); + Map capturedMdc = MdcContextPropagation.capture(); + delegate.execute(() -> { + Runnable restorePreviousContext = FlowContextHolder.adopt(capturedContext); + Runnable restorePreviousMdc = MdcContextPropagation.adopt(capturedMdc); + try { + command.run(); + } finally { + restorePreviousContext.run(); + restorePreviousMdc.run(); + } + }); + } +} diff --git a/logged-spring/src/main/java/com/fayupable/logged/spring/aspect/FlowContextTaskDecorator.java b/logged-spring/src/main/java/com/fayupable/logged/spring/aspect/FlowContextTaskDecorator.java new file mode 100644 index 0000000..0f04077 --- /dev/null +++ b/logged-spring/src/main/java/com/fayupable/logged/spring/aspect/FlowContextTaskDecorator.java @@ -0,0 +1,79 @@ +package com.fayupable.logged.spring.aspect; + +import com.fayupable.logged.core.model.FlowContext; +import org.jspecify.annotations.NonNull; +import org.springframework.core.task.TaskDecorator; + +import java.util.Map; + +/** + * {@link TaskDecorator} that carries the submitting thread's + * {@link FlowContext} and {@link org.slf4j.MDC} context into whatever thread + * Spring's {@code @Async} infrastructure actually runs the task on. + * + *

Unlike {@link FlowContextPropagatingExecutor}, which a consuming + * application wraps around an {@link java.util.concurrent.Executor} it + * manages directly, {@code @Async} methods are dispatched by Spring's own + * {@link org.springframework.core.task.TaskExecutor} machinery, which the + * calling code never sees or controls directly. {@link TaskDecorator} is + * the extension point Spring itself provides for exactly this situation: it + * decorates every {@link Runnable} submitted to a + * {@link org.springframework.core.task.support.TaskExecutorAdapter} or + * {@code ThreadPoolTaskExecutor} before it is dispatched, regardless of + * which underlying thread pool executes it. + * + *

This class deliberately does not wire itself into every + * {@code TaskExecutor} bean automatically. Auto-attaching to any executor + * found in the application context would decorate executors the consuming + * application did not intend for this library to touch, which is a + * surprising, hard-to-diagnose side effect. Instead, a consuming + * application registers this decorator explicitly on the specific executor + * it wants {@code @Logged} call chains to survive across: + * + * 

{@code
+ * @Bean
+ * public TaskExecutor taskExecutor() {
+ *     ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor();
+ *     executor.setTaskDecorator(new FlowContextTaskDecorator());
+ *     executor.initialize();
+ *     return executor;
+ * }
+ * }
+ * + *

Without this registration, a {@code @Logged} method invoked through + * {@code @Async} starts a brand new call chain instead of continuing the + * caller's: the trace id changes and the depth resets to zero, breaking the + * ability to reconstruct the full call chain from log output. + */ +public final class FlowContextTaskDecorator implements TaskDecorator { + + /** + * Captures the calling thread's current {@link FlowContext} and MDC + * context map, and returns a wrapped task that restores both before + * running {@code runnable} and restores the executor thread's own + * previous state again afterward, regardless of whether {@code runnable} + * completes normally or throws. + * + *

The MDC context map is captured and restored in full, not limited + * to {@link LoggedMdcKeys}: see {@link MdcContextPropagation} for why. + * + * @param runnable the task Spring's {@code @Async} infrastructure is + * about to hand off to an executor thread + * @return a task carrying the calling thread's flow context and MDC + */ + @Override + public Runnable decorate(@NonNull Runnable runnable) { + FlowContext capturedContext = FlowContextHolder.snapshot(); + Map capturedMdc = MdcContextPropagation.capture(); + return () -> { + Runnable restorePreviousContext = FlowContextHolder.adopt(capturedContext); + Runnable restorePreviousMdc = MdcContextPropagation.adopt(capturedMdc); + try { + runnable.run(); + } finally { + restorePreviousContext.run(); + restorePreviousMdc.run(); + } + }; + } +} diff --git a/logged-spring/src/main/java/com/fayupable/logged/spring/aspect/LoggedAspect.java b/logged-spring/src/main/java/com/fayupable/logged/spring/aspect/LoggedAspect.java index 93f918f..eb37321 100644 --- a/logged-spring/src/main/java/com/fayupable/logged/spring/aspect/LoggedAspect.java +++ b/logged-spring/src/main/java/com/fayupable/logged/spring/aspect/LoggedAspect.java @@ -1,6 +1,7 @@ package com.fayupable.logged.spring.aspect; import com.fayupable.logged.core.annotation.Logged; +import com.fayupable.logged.core.model.FlowContext; import com.fayupable.logged.core.model.MethodInvocationEvent; import com.fayupable.logged.core.port.IClientInfoPort; import com.fayupable.logged.core.port.InvocationEventEmitter; @@ -8,11 +9,19 @@ import org.aspectj.lang.ProceedingJoinPoint; import org.aspectj.lang.annotation.Around; import org.aspectj.lang.annotation.Aspect; +import org.aspectj.lang.reflect.MethodSignature; import org.slf4j.Logger; import org.slf4j.LoggerFactory; import org.springframework.stereotype.Component; +import java.lang.reflect.Method; import java.time.Instant; +import java.util.Collections; +import java.util.IdentityHashMap; +import java.util.Set; +import java.util.concurrent.CompletableFuture; +import java.util.concurrent.CompletionException; +import java.util.concurrent.ConcurrentHashMap; /** * Spring AOP interceptor that implements the behavior described by @@ -46,21 +55,104 @@ * observability collaborator could replace the intercepted method's own * exception in a {@code finally} block, hiding the real failure behind an * unrelated one from this library's own bookkeeping. + * + *

The class and method name reported for each invocation are resolved + * once per distinct {@code (target class, method)} pair and cached + * afterward in {@link #methodNameCache}, instead of being recomputed on + * every single call. {@link Class#getSimpleName()} and + * {@link Method#getName()} are cheap individually, but on a method called + * thousands of times per second the repeated string production adds up; + * caching removes it entirely after the first call. This cache is bounded + * by the number of distinct {@code @Logged} methods actually invoked in the + * running application, a quantity fixed by the codebase itself, not by + * request volume or any user-supplied value, so it cannot grow without + * bound the way a cache keyed by request data could. + * + *

On failure, this aspect reports two exception types rather than one: + * {@link MethodInvocationEvent#exceptionType()}, the type actually thrown + * across the {@code @Logged} boundary, and + * {@link MethodInvocationEvent#rootCauseType()}, the type at the end of that + * exception's {@link Throwable#getCause()} chain. A generic wrapper + * exception at the boundary (for example a framework's checked-exception + * translation) would otherwise hide which lower-level failure actually + * occurred; walking to the root cause recovers that detail while still + * reporting only class names, never exception messages. + * + *

A {@code @Logged} method that returns a {@link CompletableFuture} is + * detected and handled differently from an ordinary synchronous method. + * {@link ProceedingJoinPoint#proceed()} returning is not the same as the + * method's work being done: it only means a {@link CompletableFuture} was + * constructed and handed back, typically before the work it represents has + * even started on another thread. Recording the invocation at that point + * would report a near-zero duration and an unconditional success, + * regardless of what the asynchronous work actually does afterward. Instead, + * this aspect defers recording until the returned future itself completes, + * via {@link CompletableFuture#whenComplete}, so the reported duration and + * outcome reflect the real asynchronous work rather than just the time it + * took to submit it. The caller identity and call-chain position are still + * captured synchronously, on the original calling thread, since resolving + * them later on whatever thread completes the future could observe + * completely different, thread-bound state (for example an HTTP request + * that is only available on the original servlet thread). + * + *

While a {@code @Logged} method runs, this aspect also writes + * {@link LoggedMdcKeys} into the current thread's {@link org.slf4j.MDC}, + * restoring whatever was there before once the call ends. This is separate + * from, and in addition to, the summary line {@link #eventEmitter} produces: + * it lets a consuming application's own log statements made from inside a + * {@code @Logged} method automatically carry the same trace id, depth, + * class, and method name, without threading that information through by + * hand. This can be disabled entirely via {@link #mdcEnabled}, for + * applications that manage MDC themselves or want to avoid the extra + * {@code MDC.put}/{@code MDC.remove} calls on a very hot path. */ @Aspect @Component public class LoggedAspect { private static final Logger log = LoggerFactory.getLogger(LoggedAspect.class); + private static final Runnable NO_OP_MDC_RESTORE = () -> { }; private final InvocationEventEmitter eventEmitter; private final MetricsRecorder metricsRecorder; private final IClientInfoPort clientInfoPort; + private final boolean mdcEnabled; + private final ConcurrentHashMap methodNameCache = new ConcurrentHashMap<>(); + /** + * Creates an aspect with MDC propagation enabled, the default for any + * consumer that does not need to disable it explicitly. + * + * @param eventEmitter collaborator that emits sampled/failed/slow + * invocations + * @param metricsRecorder collaborator that records every invocation as + * a metric + * @param clientInfoPort collaborator that resolves the caller's + * identity + */ public LoggedAspect(InvocationEventEmitter eventEmitter, MetricsRecorder metricsRecorder, IClientInfoPort clientInfoPort) { + this(eventEmitter, metricsRecorder, clientInfoPort, true); + } + + /** + * Creates an aspect with explicit control over MDC propagation. + * + * @param eventEmitter collaborator that emits sampled/failed/slow + * invocations + * @param metricsRecorder collaborator that records every invocation as + * a metric + * @param clientInfoPort collaborator that resolves the caller's + * identity + * @param mdcEnabled whether {@link LoggedMdcKeys} should be written + * to the current thread's MDC while a + * {@code @Logged} method runs + */ + public LoggedAspect(InvocationEventEmitter eventEmitter, MetricsRecorder metricsRecorder, + IClientInfoPort clientInfoPort, boolean mdcEnabled) { this.eventEmitter = eventEmitter; this.metricsRecorder = metricsRecorder; this.clientInfoPort = clientInfoPort; + this.mdcEnabled = mdcEnabled; } /** @@ -68,6 +160,18 @@ public LoggedAspect(InvocationEventEmitter eventEmitter, MetricsRecorder metrics * duration and outcome, and delegating the emission decision and * call-chain tracking to their respective collaborators. * + *

The captured class name is resolved from {@link ProceedingJoinPoint#getTarget()} + * rather than {@link ProceedingJoinPoint#getSignature()}, since the + * latter reports the type on which the intercepted method is declared. + * When {@code @Logged} is placed on a method declared by an interface + * (for example {@code UserService}) and implemented by a concrete class + * (for example {@code UserServiceImpl}), resolving from the signature + * would report the interface name instead of the class actually + * handling the call. {@code getTarget()} returns the real object being + * advised, so the reported class name always matches what is actually + * running, regardless of whether the annotated method is declared on + * an interface or directly on the class. + * * @param pjp the join point representing the intercepted call * @param logged the {@link Logged} annotation present on the * intercepted method @@ -77,40 +181,235 @@ public LoggedAspect(InvocationEventEmitter eventEmitter, MetricsRecorder metrics */ @Around("@annotation(logged)") public Object logInvocation(ProceedingJoinPoint pjp, Logged logged) throws Throwable { - String className = pjp.getSignature().getDeclaringType().getSimpleName(); - String methodName = pjp.getSignature().getName(); + ResolvedNames names = resolveNames(pjp); + String className = names.className(); + String methodName = names.methodName(); + String callerIdentity = clientInfoPort.resolveCallerIdentity(); long start = System.nanoTime(); - boolean success = false; - String exceptionType = null; FlowContextHolder.FlowScope flowScope = FlowContextHolder.enter(); + Runnable restoreMdc = mdcEnabled + ? MdcPropagation.push(flowScope.context(), className, methodName) + : NO_OP_MDC_RESTORE; try { - Object result = pjp.proceed(); - success = true; + Object result; + try { + result = pjp.proceed(); + } catch (Throwable t) { + String exceptionType = t.getClass().getSimpleName(); + String rootCauseType = resolveRootCauseType(t); + long durationNanos = System.nanoTime() - start; + recordObservability(logged, className, methodName, callerIdentity, durationNanos, + false, exceptionType, rootCauseType, flowScope.context()); + throw t; + } + + if (result instanceof CompletableFuture future) { + FlowContext capturedContext = flowScope.context(); + return instrumentCompletableFuture(future, logged, className, methodName, callerIdentity, start, capturedContext); + } + + long durationNanos = System.nanoTime() - start; + recordObservability(logged, className, methodName, callerIdentity, durationNanos, + true, null, null, flowScope.context()); return result; - } catch (Throwable t) { - exceptionType = t.getClass().getSimpleName(); - throw t; } finally { - long durationNanos = System.nanoTime() - start; - recordObservability(logged, className, methodName, durationNanos, success, exceptionType, flowScope); + // Runs even if recordObservability lets an Error escape (it only + // catches RuntimeException, deliberately - see its own Javadoc), + // so this thread's FlowContext/MDC state is never left behind. + restoreMdc.run(); flowScope.close(); } } - private void recordObservability(Logged logged, String className, String methodName, long durationNanos, - boolean success, String exceptionType, FlowContextHolder.FlowScope flowScope) { + /** + * Attaches a completion callback to {@code future} that records the + * invocation once the asynchronous work it represents actually + * finishes, instead of when {@code future} was merely constructed and + * returned. + * + *

{@code flowScope} is deliberately not passed here and is closed by + * the caller before this method attaches anything: {@link + * FlowContextHolder.FlowScope#close()} restores this call's {@link + * ThreadLocal}-backed context on the thread that opened it, and the + * thread that eventually completes {@code future} is frequently a + * different one. Calling {@code close()} from that other thread would + * incorrectly overwrite whatever {@link FlowContext} belongs to it. Only + * {@code capturedContext} — an immutable snapshot of the trace id and + * depth this call was assigned — is carried into the callback, which is + * enough to report the correct call-chain position without touching any + * thread's {@link ThreadLocal} state. + * + * @param future the future returned by the intercepted method + * @param logged the {@link Logged} annotation present on the + * intercepted method + * @param className the class name resolved for this invocation + * @param methodName the method name resolved for this invocation + * @param callerIdentity the caller identity resolved synchronously on + * the original calling thread + * @param start the {@link System#nanoTime()} reading taken + * when this invocation began + * @param capturedContext the call-chain position this invocation was + * assigned, captured before the flow scope was + * closed + * @return {@code future} itself, so callers observe the same + * asynchronous result as if this aspect were not present + */ + private CompletableFuture instrumentCompletableFuture(CompletableFuture future, Logged logged, + String className, String methodName, String callerIdentity, + long start, FlowContext capturedContext) { + return future.whenComplete((value, throwable) -> { + long durationNanos = System.nanoTime() - start; + boolean success = throwable == null; + String exceptionType = null; + String rootCauseType = null; + + if (throwable != null) { + Throwable unwrapped = unwrapCompletionException(throwable); + exceptionType = unwrapped.getClass().getSimpleName(); + rootCauseType = resolveRootCauseType(unwrapped); + } + + recordObservability(logged, className, methodName, callerIdentity, durationNanos, + success, exceptionType, rootCauseType, capturedContext); + }); + } + + /** + * Unwraps a {@link CompletionException} to the actual failure it + * carries as its cause, or returns {@code thrown} unchanged if it is + * not a {@link CompletionException} or has no cause. + * + *

{@link CompletableFuture} wraps an exception thrown by a chained + * stage (for example {@code thenApply}) in a {@link CompletionException} + * before delivering it to {@link CompletableFuture#whenComplete}. This + * wrapper is an artifact of how {@link CompletableFuture} propagates + * failures, not a failure a consuming application's code ever threw; + * reporting it as {@code exceptionType} would always show the same + * uninformative wrapper type instead of the actual business exception. + * Exceptions thrown directly by a future created with + * {@link CompletableFuture#supplyAsync(java.util.function.Supplier)} are + * delivered without this wrapper, so this method only unwraps when the + * wrapper is actually present. + * + * @param thrown the throwable delivered to {@link + * CompletableFuture#whenComplete} + * @return the underlying failure, or {@code thrown} itself if there is + * no {@link CompletionException} wrapper to remove + */ + private Throwable unwrapCompletionException(Throwable thrown) { + return (thrown instanceof CompletionException) && thrown.getCause() != null ? thrown.getCause() : thrown; + } + + /** + * Walks {@link Throwable#getCause()} to the deepest cause reachable from + * {@code thrown} and returns its simple class name. + * + *

Frameworks routinely wrap a lower-level failure inside a more + * generic exception type as it propagates up the call stack; a database + * driver's connection error, for example, may surface at the + * {@code @Logged} boundary as a generic Spring {@code DataAccessException} + * with the original exception attached as its cause. Reporting only + * {@code thrown.getClass()} would hide which failure actually occurred. + * This method returns the type at the end of the cause chain instead, + * which is the original failure in the common wrapping case. When + * {@code thrown} has no cause, it is its own root, so this returns the + * same simple name already captured as {@code exceptionType}. + * + *

A cause chain is walked rather than trusted to terminate on its own + * because a misbehaving {@link Throwable} subclass could return itself + * (or otherwise form a cycle) from {@link Throwable#getCause()}. Guarding + * against already-visited instances with an identity set prevents such a + * cycle from turning this into an infinite loop. + * + * @param thrown the exception caught at the {@code @Logged} boundary + * @return the simple class name of the deepest cause in the chain + */ + private String resolveRootCauseType(Throwable thrown) { + Set visited = Collections.newSetFromMap(new IdentityHashMap<>()); + Throwable current = thrown; + visited.add(current); + + Throwable cause = current.getCause(); + while (cause != null && visited.add(cause)) { + current = cause; + cause = current.getCause(); + } + return current.getClass().getSimpleName(); + } + + /** + * Records the outcome of a single invocation through {@link + * #metricsRecorder} and, if {@link EmissionPolicy} selects it, through + * {@link #eventEmitter}. + * + *

Takes an already-resolved {@code callerIdentity} and {@link + * FlowContext} rather than resolving them itself, so this method works + * identically whether it is called synchronously, right after {@link + * ProceedingJoinPoint#proceed()} returns, or later from a {@link + * CompletableFuture} completion callback running on a different thread: + * neither value depends on {@link ThreadLocal} state at the point this + * method runs. + */ + private void recordObservability(Logged logged, String className, String methodName, String callerIdentity, + long durationNanos, boolean success, String exceptionType, String rootCauseType, + FlowContext context) { try { metricsRecorder.record(className, methodName, durationNanos, success, exceptionType); if (EmissionPolicy.shouldEmit(logged, durationNanos, success)) { eventEmitter.emit(new MethodInvocationEvent( - className, methodName, Instant.now(), durationNanos, success, exceptionType, - clientInfoPort.resolveCallerIdentity(), flowScope.context().traceId(), flowScope.context().depth() + className, methodName, Instant.now(), durationNanos, success, exceptionType, rootCauseType, + callerIdentity, context.traceId(), context.depth() )); } } catch (RuntimeException e) { log.warn("Ignoring failure while recording observability data for {}.{}", className, methodName, e); } } + + /** + * Resolves the class and method name to report for this join point, + * consulting {@link #methodNameCache} first and computing and caching + * them only on the first call for a given {@code (target class, + * method)} pair. + * + * @param pjp the join point representing the intercepted call + * @return the class and method name to report for this invocation + */ + private ResolvedNames resolveNames(ProceedingJoinPoint pjp) { + Method method = ((MethodSignature) pjp.getSignature()).getMethod(); + MethodKey key = new MethodKey(pjp.getTarget().getClass(), method); + return methodNameCache.computeIfAbsent(key, + k -> new ResolvedNames(k.targetClass().getSimpleName(), k.method().getName())); + } + + /** + * Cache key identifying a single {@code (target class, method)} pair. + * + *

Both components already have well-defined, identity-independent + * {@code equals}/{@code hashCode} implementations ({@link Class} compares + * by the class it represents, {@link Method} by its declaring class, + * name, and parameter types), so this record is safe to use as a + * {@link ConcurrentHashMap} key without any custom equality logic. + * + * @param targetClass the runtime class of the object the intercepted + * method was invoked on, as resolved by + * {@link ProceedingJoinPoint#getTarget()} + * @param method the intercepted method itself + */ + private record MethodKey(Class targetClass, Method method) { + } + + /** + * The class and method name resolved for a single {@link MethodKey}, + * cached so that {@link Class#getSimpleName()} and + * {@link Method#getName()} are each computed only once per distinct + * intercepted method. + * + * @param className the simple name of the target class + * @param methodName the name of the intercepted method + */ + private record ResolvedNames(String className, String methodName) { + } } \ No newline at end of file diff --git a/logged-spring/src/main/java/com/fayupable/logged/spring/aspect/LoggedMdcKeys.java b/logged-spring/src/main/java/com/fayupable/logged/spring/aspect/LoggedMdcKeys.java new file mode 100644 index 0000000..edfd07d --- /dev/null +++ b/logged-spring/src/main/java/com/fayupable/logged/spring/aspect/LoggedMdcKeys.java @@ -0,0 +1,53 @@ +package com.fayupable.logged.spring.aspect; + +import org.slf4j.MDC; + +/** + * The {@link MDC} key names this library writes to while a {@code @Logged} + * method is executing. + * + *

These keys are public and stable: a consuming application references + * them directly in its own logging configuration (a Logback pattern layout, + * a JSON encoder's field mappings, and so on) to have every log statement + * made during a {@code @Logged} call — not just the summary line this + * library itself emits — automatically carry the call's trace id, depth, + * class, and method name. Without this, correlating an application's own + * {@code log.info(...)} calls with a specific invocation in a structured + * logging backend (Loki, ELK) requires manually threading that information + * through every log statement by hand. + * + *

Every key is prefixed with {@code logged.} specifically to avoid + * colliding with an MDC key a consuming application, or another library, + * already uses for its own purposes (a bare {@code traceId} key, for + * example, is common enough that a collision would be likely without this + * prefix). + */ +public final class LoggedMdcKeys { + + /** + * The {@link com.fayupable.logged.core.model.FlowContext#traceId()} + * shared by every call in the same call chain. + */ + public static final String TRACE_ID = "logged.traceId"; + + /** + * The {@link com.fayupable.logged.core.model.FlowContext#depth()} of + * the currently executing call within its chain, as a string. + */ + public static final String DEPTH = "logged.depth"; + + /** + * The class name resolved for the currently executing invocation, the + * same value reported as {@link com.fayupable.logged.core.model.MethodInvocationEvent#className()}. + */ + public static final String CLASS_NAME = "logged.className"; + + /** + * The method name resolved for the currently executing invocation, the + * same value reported as {@link com.fayupable.logged.core.model.MethodInvocationEvent#methodName()}. + */ + public static final String METHOD_NAME = "logged.methodName"; + + private LoggedMdcKeys() { + } +} diff --git a/logged-spring/src/main/java/com/fayupable/logged/spring/aspect/MdcContextPropagation.java b/logged-spring/src/main/java/com/fayupable/logged/spring/aspect/MdcContextPropagation.java new file mode 100644 index 0000000..274f42c --- /dev/null +++ b/logged-spring/src/main/java/com/fayupable/logged/spring/aspect/MdcContextPropagation.java @@ -0,0 +1,67 @@ +package com.fayupable.logged.spring.aspect; + +import org.slf4j.MDC; + +import java.util.Map; + +/** + * Captures and restores the current thread's entire {@link MDC} context map + * across a thread boundary, mirroring {@link FlowContextHolder}'s + * {@code snapshot()}/{@code adopt()} pair but for the full MDC map rather + * than a single {@link com.fayupable.logged.core.model.FlowContext}. + * + *

This intentionally captures every MDC entry present on the submitting + * thread, not only {@link LoggedMdcKeys}. {@link FlowContextPropagatingExecutor} + * and {@link FlowContextTaskDecorator} are general-purpose thread-boundary + * crossers: a consuming application's own MDC entries (a request id set by + * a web filter, for example) are just as much at risk of being lost across + * a thread hop as this library's own, and there is no reason this library's + * propagation should only rescue its own keys while leaving everything else + * behind. + * + *

Package-private: this is an internal detail shared by + * {@link FlowContextPropagatingExecutor} and {@link FlowContextTaskDecorator}, + * not part of this library's public API. + */ +final class MdcContextPropagation { + + private MdcContextPropagation() { + } + + /** + * Returns a copy of the current thread's MDC context map, or + * {@code null} if it has none. + * + * @return the current thread's MDC context map, or {@code null} + */ + static Map capture() { + return MDC.getCopyOfContextMap(); + } + + /** + * Makes {@code context} the active MDC context map on the calling + * thread and returns a {@link Runnable} that undoes this, restoring + * whatever map was active before this call. + * + * @param context the MDC context map captured by {@link #capture()} on + * the thread that is handing off work, or {@code null} + * if that thread had none + * @return a {@link Runnable} that restores this thread's previous MDC + * context map; never {@code null} + */ + static Runnable adopt(Map context) { + Map previous = MDC.getCopyOfContextMap(); + if (context == null) { + MDC.clear(); + } else { + MDC.setContextMap(context); + } + return () -> { + if (previous == null) { + MDC.clear(); + } else { + MDC.setContextMap(previous); + } + }; + } +} diff --git a/logged-spring/src/main/java/com/fayupable/logged/spring/aspect/MdcPropagation.java b/logged-spring/src/main/java/com/fayupable/logged/spring/aspect/MdcPropagation.java new file mode 100644 index 0000000..3f9bff2 --- /dev/null +++ b/logged-spring/src/main/java/com/fayupable/logged/spring/aspect/MdcPropagation.java @@ -0,0 +1,66 @@ +package com.fayupable.logged.spring.aspect; + +import com.fayupable.logged.core.model.FlowContext; +import org.slf4j.MDC; + +/** + * Writes {@link LoggedMdcKeys} into the current thread's {@link MDC} for the + * duration of a single {@code @Logged} invocation, and restores whatever was + * there before once that invocation ends. + * + *

Package-private: this is an internal detail of {@link LoggedAspect} + * mirroring {@link FlowContextHolder}'s enter/close lifecycle, not part of + * this library's public API. {@link LoggedMdcKeys} is the public surface a + * consuming application actually interacts with. + * + *

Previous values are restored rather than simply removed, for the same + * reason {@link FlowContextHolder} restores rather than clears: a nested + * {@code @Logged} call must not permanently erase the outer call's MDC + * entries once the nested call returns. Restoring instead of removing keeps + * this correct regardless of nesting depth. + */ +final class MdcPropagation { + + private MdcPropagation() { + } + + /** + * Writes {@code context}, {@code className}, and {@code methodName} into + * the current thread's MDC under {@link LoggedMdcKeys}, and returns a + * {@link Runnable} that restores whatever value each key held before + * this call, once run. + * + * @param context the call-chain position of the invocation currently + * starting + * @param className the class name resolved for this invocation + * @param methodName the method name resolved for this invocation + * @return a {@link Runnable} that undoes this write; must be run once + * the invocation ends, typically in a {@code finally} block + */ + static Runnable push(FlowContext context, String className, String methodName) { + String previousTraceId = MDC.get(LoggedMdcKeys.TRACE_ID); + String previousDepth = MDC.get(LoggedMdcKeys.DEPTH); + String previousClassName = MDC.get(LoggedMdcKeys.CLASS_NAME); + String previousMethodName = MDC.get(LoggedMdcKeys.METHOD_NAME); + + MDC.put(LoggedMdcKeys.TRACE_ID, context.traceId()); + MDC.put(LoggedMdcKeys.DEPTH, String.valueOf(context.depth())); + MDC.put(LoggedMdcKeys.CLASS_NAME, className); + MDC.put(LoggedMdcKeys.METHOD_NAME, methodName); + + return () -> { + restore(LoggedMdcKeys.TRACE_ID, previousTraceId); + restore(LoggedMdcKeys.DEPTH, previousDepth); + restore(LoggedMdcKeys.CLASS_NAME, previousClassName); + restore(LoggedMdcKeys.METHOD_NAME, previousMethodName); + }; + } + + private static void restore(String key, String previousValue) { + if (previousValue == null) { + MDC.remove(key); + } else { + MDC.put(key, previousValue); + } + } +} diff --git a/logged-spring/src/main/java/com/fayupable/logged/spring/config/LoggedAutoConfiguration.java b/logged-spring/src/main/java/com/fayupable/logged/spring/config/LoggedAutoConfiguration.java index b949e72..222a667 100644 --- a/logged-spring/src/main/java/com/fayupable/logged/spring/config/LoggedAutoConfiguration.java +++ b/logged-spring/src/main/java/com/fayupable/logged/spring/config/LoggedAutoConfiguration.java @@ -116,7 +116,8 @@ public MetricsRecorder noOpMetricsRecorder() { @Bean @ConditionalOnMissingBean(LoggedAspect.class) @ConditionalOnProperty(prefix = "logged", name = "enabled", havingValue = "true", matchIfMissing = true) - public LoggedAspect loggedAspect(InvocationEventEmitter eventEmitter, MetricsRecorder metricsRecorder, IClientInfoPort clientInfoPort) { - return new LoggedAspect(eventEmitter, metricsRecorder, clientInfoPort); + public LoggedAspect loggedAspect(InvocationEventEmitter eventEmitter, MetricsRecorder metricsRecorder, + IClientInfoPort clientInfoPort, LoggedProperties properties) { + return new LoggedAspect(eventEmitter, metricsRecorder, clientInfoPort, properties.getMdc().isEnabled()); } } \ No newline at end of file diff --git a/logged-spring/src/main/java/com/fayupable/logged/spring/config/LoggedProperties.java b/logged-spring/src/main/java/com/fayupable/logged/spring/config/LoggedProperties.java index 657deb4..7a3a471 100644 --- a/logged-spring/src/main/java/com/fayupable/logged/spring/config/LoggedProperties.java +++ b/logged-spring/src/main/java/com/fayupable/logged/spring/config/LoggedProperties.java @@ -25,6 +25,7 @@ public class LoggedProperties { private final ClientInfo clientInfo = new ClientInfo(); private final Metrics metrics = new Metrics(); + private final Mdc mdc = new Mdc(); public boolean isEnabled() { return enabled; @@ -42,6 +43,10 @@ public Metrics getMetrics() { return metrics; } + public Mdc getMdc() { + return mdc; + } + /** * Properties controlling how the caller's identity is resolved. */ @@ -91,4 +96,28 @@ public void setEnabled(boolean enabled) { this.enabled = enabled; } } + + /** + * Properties controlling MDC propagation. + */ + public static class Mdc { + + /** + * Whether {@link com.fayupable.logged.spring.aspect.LoggedMdcKeys} + * are written to the current thread's MDC while a {@code @Logged} + * method runs. Defaults to {@code true}. Disabling this is useful + * for an application that manages its own MDC entries and wants to + * avoid any risk of key collision, or that wants to avoid the extra + * {@code MDC.put}/{@code MDC.remove} calls on a very hot path. + */ + private boolean enabled = true; + + public boolean isEnabled() { + return enabled; + } + + public void setEnabled(boolean enabled) { + this.enabled = enabled; + } + } } \ No newline at end of file diff --git a/logged-spring/src/main/java/com/fayupable/logged/spring/emitter/Slf4jInvocationEventEmitter.java b/logged-spring/src/main/java/com/fayupable/logged/spring/emitter/Slf4jInvocationEventEmitter.java index 4d1ecc5..6f24f00 100644 --- a/logged-spring/src/main/java/com/fayupable/logged/spring/emitter/Slf4jInvocationEventEmitter.java +++ b/logged-spring/src/main/java/com/fayupable/logged/spring/emitter/Slf4jInvocationEventEmitter.java @@ -20,6 +20,12 @@ * that is, when the call is part of a chain of nested {@code @Logged} * invocations. Root-level, non-nested calls are logged without this extra * detail, keeping the common case concise. + * + *

{@link MethodInvocationEvent#rootCauseType()} is only appended to a + * failure line when it differs from {@link MethodInvocationEvent#exceptionType()}, + * that is, when the thrown exception actually wraps a different underlying + * cause. When the two are equal, showing the root cause a second time would + * add nothing, so it is omitted to keep the common case concise. */ public class Slf4jInvocationEventEmitter implements InvocationEventEmitter { @@ -36,8 +42,12 @@ public void emit(MethodInvocationEvent event) { log.info("[{}] {}.{} completed in {}ms{}", event.callerIdentity(), event.className(), event.methodName(), durationMs, chainSuffix); } else { - log.warn("[{}] {}.{} failed after {}ms - {}{}", - event.callerIdentity(), event.className(), event.methodName(), durationMs, event.exceptionType(), chainSuffix); + boolean rootCauseDiffers = event.rootCauseType() != null && !event.rootCauseType().equals(event.exceptionType()); + String causeSuffix = rootCauseDiffers ? " (caused by " + event.rootCauseType() + ")" : ""; + + log.warn("[{}] {}.{} failed after {}ms - {}{}{}", + event.callerIdentity(), event.className(), event.methodName(), durationMs, + event.exceptionType(), causeSuffix, chainSuffix); } } } diff --git a/logged-spring/src/main/java/com/fayupable/logged/spring/guard/LoggedTargetGuardBeanPostProcessor.java b/logged-spring/src/main/java/com/fayupable/logged/spring/guard/LoggedTargetGuardBeanPostProcessor.java index 4909e34..68fe884 100644 --- a/logged-spring/src/main/java/com/fayupable/logged/spring/guard/LoggedTargetGuardBeanPostProcessor.java +++ b/logged-spring/src/main/java/com/fayupable/logged/spring/guard/LoggedTargetGuardBeanPostProcessor.java @@ -6,43 +6,66 @@ import org.springframework.beans.factory.config.BeanPostProcessor; import java.lang.annotation.Annotation; -import java.util.Arrays; +import java.lang.reflect.Method; +import java.util.ArrayList; +import java.util.List; /** - * Fails application startup when {@link Logged} is applied to a method on a - * class that should never carry observability instrumentation: a JPA - * entity, a Spring Data repository interface implementation, or a class - * annotated with {@code @Repository}. + * Fails application startup when {@link Logged} is applied to a method that + * cannot be correctly instrumented: a method on a JPA entity, a Spring Data + * repository interface implementation, a class annotated with + * {@code @Repository}, or a method returning a reactive + * {@code org.reactivestreams.Publisher} (Reactor's {@code Mono}/{@code Flux}, + * or an RxJava adapter that implements the same interface). * - *

Instrumenting these layers is almost always a mistake. Entities are - * plain data holders whose getters can be invoked extremely frequently - * (for example during JSON serialization or JPA dirty checking), turning a - * single request into thousands of log lines and metric updates. + *

Instrumenting an entity or repository is almost always a mistake. + * Entities are plain data holders whose getters can be invoked extremely + * frequently (for example during JSON serialization or JPA dirty checking), + * turning a single request into thousands of log lines and metric updates. * Repositories are already covered by lower-level persistence metrics * (query timing, connection pool statistics); wrapping every repository * call in the same interceptor as business logic tends to blur, rather * than clarify, what is slow. * + *

A method returning a reactive {@code Publisher} cannot be correctly + * instrumented by this library today for a different reason: {@code @Logged} + * only defers its duration/outcome recording for {@link + * java.util.concurrent.CompletableFuture}, via {@code whenComplete}. A + * reactive type built with Project Reactor or RxJava is lazy — nothing runs + * until something subscribes — so {@code ProceedingJoinPoint#proceed()} + * returning only means the pipeline was assembled, not that it ran. Silently + * recording at that point would report a near-zero duration and + * unconditional success regardless of what the reactive pipeline actually + * does once subscribed to, which is worse than not measuring it at all: it + * looks like real data. Rejecting it at startup is preferred over recording + * something misleading; full reactive support (bridging {@code FlowContext} + * and MDC through Reactor's {@code Context}) is a substantially larger + * feature, not yet implemented. + * *

This check runs once per bean, before Spring's AOP auto-proxy creator * wraps the bean, so it inspects the original target class rather than a * proxy. It intentionally does not import {@code jakarta.persistence.Entity}, - * {@code org.springframework.stereotype.Repository}, or - * {@code org.springframework.data.repository.Repository} directly, and - * instead compares fully qualified names through reflection. This keeps - * this module free of a hard dependency on JPA or Spring Data, so consumers - * who use neither are not forced to bring them onto the classpath. + * {@code org.springframework.stereotype.Repository}, + * {@code org.springframework.data.repository.Repository}, or + * {@code org.reactivestreams.Publisher} directly, and instead compares fully + * qualified names through reflection. This keeps this module free of a hard + * dependency on JPA, Spring Data, or a reactive streams implementation, so + * consumers who use none of these are not forced to bring them onto the + * classpath. */ public class LoggedTargetGuardBeanPostProcessor implements BeanPostProcessor { private static final String JPA_ENTITY_ANNOTATION = "jakarta.persistence.Entity"; private static final String SPRING_REPOSITORY_ANNOTATION = "org.springframework.stereotype.Repository"; private static final String SPRING_DATA_REPOSITORY_INTERFACE = "org.springframework.data.repository.Repository"; + private static final String REACTIVE_PUBLISHER_INTERFACE = "org.reactivestreams.Publisher"; @Override public Object postProcessBeforeInitialization(Object bean, @NonNull String beanName) throws BeansException { Class targetClass = bean.getClass(); + List loggedMethods = findLoggedMethods(targetClass); - if (hasLoggedMethod(targetClass) && isDisallowedTarget(targetClass)) { + if (!loggedMethods.isEmpty() && isDisallowedTarget(targetClass)) { throw new IllegalStateException( "@Logged is not allowed on class " + targetClass.getName() + " (bean '" + beanName + "'): " + "entities, @Repository beans, and Spring Data repository implementations must not " @@ -51,12 +74,47 @@ public Object postProcessBeforeInitialization(Object bean, @NonNull String beanN ); } + for (Method method : loggedMethods) { + if (implementsInterfaceNamed(method.getReturnType(), REACTIVE_PUBLISHER_INTERFACE)) { + throw new IllegalStateException( + "@Logged is not supported on method " + targetClass.getName() + "#" + method.getName() + + " (bean '" + beanName + "'): it returns " + method.getReturnType().getName() + + ", a reactive publisher. Recording would measure only how long the pipeline took " + + "to assemble, not the actual asynchronous work, and would always report success " + + "even if the pipeline later fails. Use CompletableFuture instead, or remove " + + "@Logged from this method until reactive support is added." + ); + } + } + return bean; } - private boolean hasLoggedMethod(Class targetClass) { - return Arrays.stream(targetClass.getDeclaredMethods()) - .anyMatch(method -> method.isAnnotationPresent(Logged.class)); + /** + * Collects every {@code @Logged}-annotated method declared anywhere in + * {@code targetClass}'s superclass chain. + * + *

Walks the superclass chain rather than checking only + * {@code targetClass.getDeclaredMethods()}, since {@code @Logged} placed + * on an abstract base class method (inherited, not redeclared, by a + * disallowed subclass such as a {@code @Repository} or JPA entity) would + * otherwise bypass this guard entirely, even though Spring AOP's own + * {@code @annotation(logged)} pointcut still intercepts that inherited + * method at runtime. + * + * @param targetClass the bean's class to inspect + * @return every {@code @Logged} method found; empty if none + */ + private List findLoggedMethods(Class targetClass) { + List loggedMethods = new ArrayList<>(); + for (Class current = targetClass; current != null && current != Object.class; current = current.getSuperclass()) { + for (Method method : current.getDeclaredMethods()) { + if (method.isAnnotationPresent(Logged.class)) { + loggedMethods.add(method); + } + } + } + return loggedMethods; } private boolean isDisallowedTarget(Class targetClass) { diff --git a/logged-spring/src/main/java/com/fayupable/logged/spring/http/FeignTraceRequestInterceptor.java b/logged-spring/src/main/java/com/fayupable/logged/spring/http/FeignTraceRequestInterceptor.java new file mode 100644 index 0000000..dee8c7e --- /dev/null +++ b/logged-spring/src/main/java/com/fayupable/logged/spring/http/FeignTraceRequestInterceptor.java @@ -0,0 +1,42 @@ +package com.fayupable.logged.spring.http; + +import feign.RequestInterceptor; +import feign.RequestTemplate; + +/** + * Feign {@link RequestInterceptor} that writes the current {@code @Logged} + * call chain's trace id and depth into an outgoing Feign client request's + * headers, via {@link HttpTraceHeaderCarrier}. + * + *

Feign clients are purely synchronous/blocking, exactly like + * {@code RestTemplate}: there is no ambiguity about which thread's {@link + * com.fayupable.logged.core.model.FlowContext} is captured, since it is + * always the thread that made the Feign call. + * + *

Register this as a Spring bean; Spring Cloud OpenFeign auto-detects any + * {@link RequestInterceptor} bean and applies it to every Feign client in + * the application: + * + * 

{@code
+ * @Bean
+ * public RequestInterceptor loggedTraceRequestInterceptor() {
+ *     return new FeignTraceRequestInterceptor();
+ * }
+ * }
+ * + *

Not wired in automatically by this library itself — declaring the bean + * above is the explicit, one-time opt-in step, the same as every other + * propagation class in this library. + */ +public final class FeignTraceRequestInterceptor implements RequestInterceptor { + + /** + * Writes the current call chain's trace headers onto {@code template}. + * + * @param template the outgoing Feign request template + */ + @Override + public void apply(RequestTemplate template) { + HttpTraceHeaderCarrier.writeToHeaders(template::header); + } +} diff --git a/logged-spring/src/main/java/com/fayupable/logged/spring/http/HttpTraceClientHttpRequestInterceptor.java b/logged-spring/src/main/java/com/fayupable/logged/spring/http/HttpTraceClientHttpRequestInterceptor.java new file mode 100644 index 0000000..e0484f6 --- /dev/null +++ b/logged-spring/src/main/java/com/fayupable/logged/spring/http/HttpTraceClientHttpRequestInterceptor.java @@ -0,0 +1,51 @@ +package com.fayupable.logged.spring.http; + +import org.jspecify.annotations.NonNull; +import org.springframework.http.HttpRequest; +import org.springframework.http.client.ClientHttpRequestExecution; +import org.springframework.http.client.ClientHttpRequestInterceptor; +import org.springframework.http.client.ClientHttpResponse; + +import java.io.IOException; + +/** + * {@link ClientHttpRequestInterceptor} that writes the current + * {@code @Logged} call chain's trace id and depth into an outgoing + * {@code RestTemplate} request's headers, via {@link HttpTraceHeaderCarrier}. + * + *

{@code RestTemplate} is purely synchronous/blocking, so — unlike + * {@link HttpTraceExchangeFilterFunction} for {@code WebClient} — there is + * no ambiguity about which thread's {@link + * com.fayupable.logged.core.model.FlowContext} is captured: it is always + * the thread that made the {@code RestTemplate} call. + * + *

Register this on the specific {@code RestTemplate} instance you want + * to carry trace context across service calls: + * + * 

{@code
+ * RestTemplate restTemplate = new RestTemplate();
+ * restTemplate.getInterceptors().add(new HttpTraceClientHttpRequestInterceptor());
+ * }
+ * + *

Not wired in automatically: a consuming application decides which + * {@code RestTemplate} instances should carry trace context, the same way + * it decides which methods get {@code @Logged} in the first place. + */ +public final class HttpTraceClientHttpRequestInterceptor implements ClientHttpRequestInterceptor { + + /** + * Writes the current call chain's trace headers onto {@code request} + * before delegating to {@code execution}. + * + * @param request the outgoing request + * @param body the outgoing request body, passed through unchanged + * @param execution delegates the actual request execution + * @return the response returned by {@code execution} + */ + @Override + public @NonNull ClientHttpResponse intercept(@NonNull HttpRequest request, @NonNull byte[] body, + @NonNull ClientHttpRequestExecution execution) throws IOException { + HttpTraceHeaderCarrier.writeToHeaders(request.getHeaders()::set); + return execution.execute(request, body); + } +} diff --git a/logged-spring/src/main/java/com/fayupable/logged/spring/http/HttpTraceExchangeFilterFunction.java b/logged-spring/src/main/java/com/fayupable/logged/spring/http/HttpTraceExchangeFilterFunction.java new file mode 100644 index 0000000..cd18c0d --- /dev/null +++ b/logged-spring/src/main/java/com/fayupable/logged/spring/http/HttpTraceExchangeFilterFunction.java @@ -0,0 +1,63 @@ +package com.fayupable.logged.spring.http; + +import org.jspecify.annotations.NonNull; +import org.springframework.web.reactive.function.client.ClientRequest; +import org.springframework.web.reactive.function.client.ClientResponse; +import org.springframework.web.reactive.function.client.ExchangeFilterFunction; +import org.springframework.web.reactive.function.client.ExchangeFunction; +import reactor.core.publisher.Mono; + +/** + * {@link ExchangeFilterFunction} that writes the current {@code @Logged} + * call chain's trace id and depth into an outgoing {@code WebClient} + * request's headers, via {@link HttpTraceHeaderCarrier}. + * + *

Thread caveat, unlike {@link HttpTraceClientHttpRequestInterceptor} + * and {@link FeignTraceRequestInterceptor}: {@code WebClient} is + * reactive, and {@link #filter} runs whenever the returned {@link Mono} is + * actually subscribed to — which, if the request is built with + * {@code subscribeOn}/{@code publishOn} or otherwise composed across + * schedulers, may not be the same thread that constructed the + * {@code WebClient} call in application code. In that case, this filter + * captures whatever {@link com.fayupable.logged.core.model.FlowContext} is + * active on the thread that actually triggers the exchange, which is not + * guaranteed to be the calling thread's. For the common case of a + * {@code @Logged} method calling {@code WebClient} and blocking on the + * result (for example via {@code .block()}), the subscribing thread and the + * calling thread are the same, and this behaves exactly like the + * {@code RestTemplate} and Feign integrations. Full correctness across an + * arbitrarily composed reactive chain would require bridging {@code + * FlowContext} through Reactor's own {@code Context}, which this library + * does not yet do (see the reactive {@code Publisher} return type + * limitation documented on {@code LoggedTargetGuardBeanPostProcessor}). + * + *

Register this on the specific {@code WebClient} instance you want to + * carry trace context across service calls: + * + * 

{@code
+ * WebClient webClient = WebClient.builder()
+ *         .filter(new HttpTraceExchangeFilterFunction())
+ *         .build();
+ * }
+ * + *

Not wired in automatically: a consuming application decides which + * {@code WebClient} instances should carry trace context, the same way it + * decides which methods get {@code @Logged} in the first place. + */ +public final class HttpTraceExchangeFilterFunction implements ExchangeFilterFunction { + + /** + * Writes the current call chain's trace headers onto a copy of + * {@code request} before delegating to {@code next}. + * + * @param request the outgoing request + * @param next delegates the actual exchange + * @return the response {@link Mono} returned by {@code next} + */ + @Override + public @NonNull Mono filter(@NonNull ClientRequest request, @NonNull ExchangeFunction next) { + ClientRequest.Builder requestWithTrace = ClientRequest.from(request); + HttpTraceHeaderCarrier.writeToHeaders(requestWithTrace::header); + return next.exchange(requestWithTrace.build()); + } +} diff --git a/logged-spring/src/main/java/com/fayupable/logged/spring/http/HttpTraceHeaderCarrier.java b/logged-spring/src/main/java/com/fayupable/logged/spring/http/HttpTraceHeaderCarrier.java new file mode 100644 index 0000000..04cda9d --- /dev/null +++ b/logged-spring/src/main/java/com/fayupable/logged/spring/http/HttpTraceHeaderCarrier.java @@ -0,0 +1,156 @@ +package com.fayupable.logged.spring.http; + +import com.fayupable.logged.core.model.FlowContext; +import com.fayupable.logged.spring.aspect.FlowContextCarrier; + +import java.util.function.BiConsumer; +import java.util.function.Function; +import java.util.regex.Pattern; + +/** + * Carries a {@code @Logged} call chain's {@link FlowContext} across a + * synchronous HTTP call, by writing it into the outgoing request's headers + * and reading it back from the incoming request's headers. + * + *

Unlike {@link com.fayupable.logged.spring.kafka.KafkaTraceHeaderCarrier} + * and {@link com.fayupable.logged.spring.rabbitmq.RabbitTraceHeaderCarrier}, + * which operate on one concrete header type each ({@code Headers}, + * {@code MessageProperties}), no single header type is common to every HTTP + * client a consuming application might use — {@code RestTemplate}, Feign, + * {@code WebClient}, and a hand-rolled {@code HttpURLConnection} each expose + * headers through a different API. This class instead operates on plain + * {@link BiConsumer}/{@link Function} references, so it can be pointed at + * whichever client's own header-writing/reading method already exists: + * + * 

{@code
+ * // RestTemplate / a plain HttpHeaders instance
+ * HttpTraceHeaderCarrier.writeToHeaders(headers::set);
+ *
+ * // Feign
+ * HttpTraceHeaderCarrier.writeToHeaders(requestTemplate::header);
+ *
+ * // java.net.HttpURLConnection
+ * HttpTraceHeaderCarrier.writeToHeaders(connection::setRequestProperty);
+ * }
+ * + *

{@link com.fayupable.logged.spring.http.HttpTraceClientHttpRequestInterceptor}, + * {@link com.fayupable.logged.spring.http.FeignTraceRequestInterceptor}, + * {@link com.fayupable.logged.spring.http.HttpTraceExchangeFilterFunction}, + * and {@link com.fayupable.logged.spring.http.HttpTraceServletFilter} are + * ready-made integrations built on top of this class for + * {@code RestTemplate}, Feign, {@code WebClient}, and inbound Servlet + * requests, respectively. A consuming application using a different HTTP + * client can still participate in cross-service tracing by calling this + * class directly, the same way those four classes do internally. + * + *

Only the {@code traceId} and {@code depth} cross the wire — never any + * other request data — under the {@value #TRACE_ID_HEADER}/ + * {@value #DEPTH_HEADER} header names. + * + *

Unlike {@link com.fayupable.logged.spring.kafka.KafkaTraceHeaderCarrier}/ + * {@link com.fayupable.logged.spring.rabbitmq.RabbitTraceHeaderCarrier}, + * whose message headers typically originate from another of a consuming + * application's own services, an HTTP request's headers can originate from + * a completely untrusted caller if the endpoint receiving it is reachable + * from outside the application's own trust boundary. Without validation, an + * external caller could set {@link #TRACE_ID_HEADER} to an arbitrary string + * — including one crafted to look like a fabricated log line, if it + * contains characters like {@code \n} and the receiving side's logging + * pattern does not escape them — which would then flow, unexamined, into + * this thread's {@code @Logged} log output and MDC. {@link #readAndAdopt} + * therefore only accepts a {@link #TRACE_ID_HEADER} value that matches the + * same shape this library itself always produces (a short hexadecimal + * string, see {@link com.fayupable.logged.core.model.FlowContext#root()}); + * anything else is treated exactly like a missing header, not merely + * logged-but-rejected, so no attacker-controlled string ever reaches this + * thread's context at all. + */ +public final class HttpTraceHeaderCarrier { + + public static final String TRACE_ID_HEADER = "X-Logged-Trace-Id"; + public static final String DEPTH_HEADER = "X-Logged-Depth"; + + /** + * Matches every {@code traceId} this library can ever itself produce + * (see {@link com.fayupable.logged.core.model.FlowContext#root()}: up to + * sixteen hexadecimal characters, the string form of a 64-bit value) and + * nothing else, so a value crafted to inject control characters (for + * example {@code \n}) into log output can never pass this check. + */ + private static final Pattern VALID_TRACE_ID = Pattern.compile("[0-9a-fA-F]{1,16}"); + + private HttpTraceHeaderCarrier() { + } + + /** + * Writes the current thread's {@link FlowContext}, if any is active, + * through {@code headerWriter} under {@link #TRACE_ID_HEADER}/ + * {@link #DEPTH_HEADER}. + * + *

Does nothing if no {@code @Logged} call is currently active on this + * thread: an outgoing request made from outside any call chain simply + * carries no trace headers, exactly as if this method had never been + * called. + * + * @param headerWriter a reference to the target's own + * {@code (name, value) -> void} header-writing + * method + */ + public static void writeToHeaders(BiConsumer headerWriter) { + FlowContext context = FlowContextCarrier.capture(); + if (context == null) { + return; + } + headerWriter.accept(TRACE_ID_HEADER, context.traceId()); + headerWriter.accept(DEPTH_HEADER, String.valueOf(context.depth())); + } + + /** + * Reads a {@link FlowContext} through {@code headerReader}, if present, + * adopts it as the active context on this thread for the duration of + * {@code work}, and restores this thread's previous context again + * afterward, regardless of whether {@code work} completes normally or + * throws. + * + *

If no {@link #TRACE_ID_HEADER} is found, or its value does not + * match {@link #VALID_TRACE_ID} — for example, a request from a caller + * that does not use this library, or one crafted by an untrusted caller + * to inject something other than a real trace id — {@code work} is + * simply run as-is, with no context adopted. Any {@code @Logged} call + * made from within it then starts a new chain of its own, exactly as it + * would without this class involved at all. + * + * @param headerReader a reference to the source's own + * {@code (name) -> String} header-reading method; + * may return {@code null} for a missing header + * @param work the request-handling code to run with the + * incoming request's trace context active + */ + public static void readAndAdopt(Function headerReader, Runnable work) { + String traceId = headerReader.apply(TRACE_ID_HEADER); + if (traceId == null || !VALID_TRACE_ID.matcher(traceId).matches()) { + work.run(); + return; + } + + FlowContext context = new FlowContext(traceId, readDepth(headerReader)); + Runnable restorePreviousContext = FlowContextCarrier.adopt(context); + try { + work.run(); + } finally { + restorePreviousContext.run(); + } + } + + private static int readDepth(Function headerReader) { + String depth = headerReader.apply(DEPTH_HEADER); + if (depth == null) { + return 0; + } + try { + return Integer.parseInt(depth); + } catch (NumberFormatException malformedDepth) { + return 0; + } + } +} diff --git a/logged-spring/src/main/java/com/fayupable/logged/spring/http/HttpTraceServletFilter.java b/logged-spring/src/main/java/com/fayupable/logged/spring/http/HttpTraceServletFilter.java new file mode 100644 index 0000000..968adcf --- /dev/null +++ b/logged-spring/src/main/java/com/fayupable/logged/spring/http/HttpTraceServletFilter.java @@ -0,0 +1,96 @@ +package com.fayupable.logged.spring.http; + +import jakarta.servlet.FilterChain; +import jakarta.servlet.ServletException; +import jakarta.servlet.http.HttpServletRequest; +import jakarta.servlet.http.HttpServletResponse; +import org.jspecify.annotations.NonNull; +import org.springframework.web.filter.OncePerRequestFilter; + +import java.io.IOException; + +/** + * Servlet {@link jakarta.servlet.Filter} that reads the incoming HTTP + * request's trace headers, if present, and adopts them as the active + * {@code @Logged} call chain for the duration of the request, via + * {@link HttpTraceHeaderCarrier}. + * + *

This is the inbound counterpart to + * {@link HttpTraceClientHttpRequestInterceptor}/{@link + * FeignTraceRequestInterceptor}/{@link HttpTraceExchangeFilterFunction}: a + * service that only sends the outbound trace headers but never reads them + * back on the receiving side would never actually observe the propagated + * chain continue — this filter is the other half of that exchange. + * + *

Register as a Spring bean, with high precedence so the adopted context + * is active for as much of the request-handling chain as possible, + * including any {@code @Logged} controller/service methods invoked further + * down the chain: + * + * 

{@code
+ * @Bean
+ * public FilterRegistrationBean httpTraceServletFilter() {
+ *     FilterRegistrationBean registration =
+ *             new FilterRegistrationBean<>(new HttpTraceServletFilter());
+ *     registration.setOrder(Ordered.HIGHEST_PRECEDENCE);
+ *     return registration;
+ * }
+ * }
+ * + *

Not wired in automatically: a consuming application decides whether it + * wants incoming requests to participate in cross-service tracing, the same + * way it decides which methods get {@code @Logged} in the first place. + */ +public final class HttpTraceServletFilter extends OncePerRequestFilter { + + /** + * Reads the incoming request's trace headers, if present, and runs the + * rest of the filter chain with them adopted as the active call chain + * for this thread, restoring this thread's previous context again + * afterward, regardless of whether the chain completes normally or + * throws. + * + * @param request the incoming HTTP request + * @param response the outgoing HTTP response, passed through + * unchanged + * @param filterChain the rest of the filter chain + */ + @Override + protected void doFilterInternal(@NonNull HttpServletRequest request, @NonNull HttpServletResponse response, + @NonNull FilterChain filterChain) throws ServletException, IOException { + try { + HttpTraceHeaderCarrier.readAndAdopt(request::getHeader, () -> { + try { + filterChain.doFilter(request, response); + } catch (ServletException | IOException e) { + throw new FilterChainExecutionException(e); + } + }); + } catch (FilterChainExecutionException wrapped) { + wrapped.rethrow(); + } + } + + /** + * Carries a checked {@link ServletException}/{@link IOException} thrown + * by {@link FilterChain#doFilter} through {@link HttpTraceHeaderCarrier#readAndAdopt}, + * whose {@code work} parameter is a plain {@link Runnable} and cannot + * declare checked exceptions itself. + */ + private static final class FilterChainExecutionException extends RuntimeException { + FilterChainExecutionException(Exception cause) { + super(cause); + } + + void rethrow() throws ServletException, IOException { + Throwable cause = getCause(); + if (cause instanceof ServletException servletException) { + throw servletException; + } + if (cause instanceof IOException ioException) { + throw ioException; + } + throw this; + } + } +} diff --git a/logged-spring/src/main/java/com/fayupable/logged/spring/kafka/KafkaTraceHeaderCarrier.java b/logged-spring/src/main/java/com/fayupable/logged/spring/kafka/KafkaTraceHeaderCarrier.java new file mode 100644 index 0000000..3443621 --- /dev/null +++ b/logged-spring/src/main/java/com/fayupable/logged/spring/kafka/KafkaTraceHeaderCarrier.java @@ -0,0 +1,133 @@ +package com.fayupable.logged.spring.kafka; + +import com.fayupable.logged.core.model.FlowContext; +import com.fayupable.logged.spring.aspect.FlowContextCarrier; +import org.apache.kafka.common.header.Header; +import org.apache.kafka.common.header.Headers; + +import java.nio.charset.StandardCharsets; +import java.util.regex.Pattern; + +/** + * Carries a {@code @Logged} call chain's {@link FlowContext} across a Kafka + * message, by writing it into the message's headers when producing and + * reading it back when consuming. + * + *

The {@code traceId} and {@code depth} are written as plain Kafka + * headers ({@link Headers}), never into the message's own key or value. + * Kafka headers exist specifically for metadata like this: they travel with + * the message but are entirely separate from whatever serialization format + * (JSON, Avro, protobuf, or anything else) the message's actual payload + * uses, so this never touches or constrains that payload's schema. + * + *

This class depends only on {@code org.apache.kafka:kafka-clients}' + * {@link Headers} interface, not {@code spring-kafka}: every Kafka producer + * and consumer, whether used directly or through Spring's own + * {@code KafkaTemplate}/{@code @KafkaListener}, exposes this same interface, + * so this works regardless of which of those a consuming application uses. + * + *

Like every propagation class in this library, nothing here is wired in + * automatically. A consuming application calls {@link #writeToHeaders} when + * producing a message and {@link #readAndAdopt} when consuming one, exactly + * where it already produces or consumes Kafka messages. + */ +public final class KafkaTraceHeaderCarrier { + + static final String TRACE_ID_HEADER = "logged-traceId"; + static final String DEPTH_HEADER = "logged-depth"; + + /** + * Matches every {@code traceId} this library can ever itself produce + * (see {@link com.fayupable.logged.core.model.FlowContext#root()}: up to + * sixteen hexadecimal characters) and nothing else. A Kafka topic's + * producers are typically other services within the same application's + * own trust boundary, unlike an HTTP endpoint that may be reachable from + * an untrusted caller, but validating here too costs nothing and keeps + * this carrier consistent with + * {@link com.fayupable.logged.spring.http.HttpTraceHeaderCarrier}. + */ + private static final Pattern VALID_TRACE_ID = Pattern.compile("[0-9a-fA-F]{1,16}"); + + private KafkaTraceHeaderCarrier() { + } + + /** + * Writes the current thread's {@link FlowContext}, if any is active, + * into {@code headers} as {@link #TRACE_ID_HEADER}/{@link #DEPTH_HEADER} + * entries. + * + *

Does nothing if no {@code @Logged} call is currently active on this + * thread: a message produced from outside any call chain simply carries + * no trace headers, exactly as if this method had never been called. + * + * @param headers the headers of the {@code ProducerRecord} about to be + * sent + */ + public static void writeToHeaders(Headers headers) { + FlowContext context = FlowContextCarrier.capture(); + if (context == null) { + return; + } + headers.add(TRACE_ID_HEADER, context.traceId().getBytes(StandardCharsets.UTF_8)); + headers.add(DEPTH_HEADER, String.valueOf(context.depth()).getBytes(StandardCharsets.UTF_8)); + } + + /** + * Reads a {@link FlowContext} from {@code headers}, if present, adopts + * it as the active context on this thread for the duration of + * {@code work}, and restores this thread's previous context again + * afterward, regardless of whether {@code work} completes normally or + * throws. + * + *

If {@code headers} carries no {@link #TRACE_ID_HEADER} — for + * example, a message produced by a service that does not use this + * library, or one produced from outside any call chain — {@code work} + * is simply run as-is, with no context adopted. Any {@code @Logged} + * call made from within it then starts a new chain of its own, exactly + * as it would without this class involved at all. + * + * @param headers the headers of the {@code ConsumerRecord} being + * processed + * @param work the message-handling code to run with the message's + * trace context active + */ + public static void readAndAdopt(Headers headers, Runnable work) { + FlowContext context = readContext(headers); + if (context == null) { + work.run(); + return; + } + + Runnable restorePreviousContext = FlowContextCarrier.adopt(context); + try { + work.run(); + } finally { + restorePreviousContext.run(); + } + } + + private static FlowContext readContext(Headers headers) { + Header traceIdHeader = headers.lastHeader(TRACE_ID_HEADER); + if (traceIdHeader == null) { + return null; + } + String traceId = new String(traceIdHeader.value(), StandardCharsets.UTF_8); + if (!VALID_TRACE_ID.matcher(traceId).matches()) { + return null; + } + int depth = readDepth(headers); + return new FlowContext(traceId, depth); + } + + private static int readDepth(Headers headers) { + Header depthHeader = headers.lastHeader(DEPTH_HEADER); + if (depthHeader == null) { + return 0; + } + try { + return Integer.parseInt(new String(depthHeader.value(), StandardCharsets.UTF_8)); + } catch (NumberFormatException malformedDepth) { + return 0; + } + } +} diff --git a/logged-spring/src/main/java/com/fayupable/logged/spring/metrics/LazyMetricsRecorder.java b/logged-spring/src/main/java/com/fayupable/logged/spring/metrics/LazyMetricsRecorder.java index a063beb..687fb33 100644 --- a/logged-spring/src/main/java/com/fayupable/logged/spring/metrics/LazyMetricsRecorder.java +++ b/logged-spring/src/main/java/com/fayupable/logged/spring/metrics/LazyMetricsRecorder.java @@ -15,12 +15,27 @@ * auto-configurations, an order this module cannot reliably pin itself * against across Spring Boot versions. Resolving lazily through * {@link ObjectProvider}, on the other hand, is unaffected by that - * ordering: by the time any {@code @Logged} method is actually invoked, - * the application context has fully started, and any {@link MeterRegistry} - * bean that is ever going to exist already does. + * ordering in the common case: by the time any {@code @Logged} method is + * actually invoked, the application context has usually fully started, and + * any {@link MeterRegistry} bean that is ever going to exist already does. + * + *

That said, a {@code @Logged} method can still be invoked earlier than + * that — for example from another bean's {@code @PostConstruct} — before a + * {@link MeterRegistry} bean has been created. Only the found + * outcome is cached in {@link #delegate}: if no {@link MeterRegistry} is + * available yet, this class deliberately does not pin itself to + * {@link NoOpMetricsRecorder} forever, and instead checks again on every + * subsequent call until one is found. Caching a negative result here would + * silently and permanently disable metrics for the rest of the + * application's lifetime the moment this class lost that one-time race, + * which is a far worse failure mode than re-checking an already-cheap + * {@link ObjectProvider#getIfAvailable()} call a few extra times early in + * the application's startup. */ public class LazyMetricsRecorder implements MetricsRecorder { + private static final MetricsRecorder NO_OP = new NoOpMetricsRecorder(); + private final ObjectProvider meterRegistryProvider; private volatile MetricsRecorder delegate; @@ -39,10 +54,14 @@ private MetricsRecorder resolveDelegate() { return resolved; } synchronized (this) { - if (delegate == null) { - MeterRegistry registry = meterRegistryProvider.getIfAvailable(); - delegate = registry != null ? new MicrometerMetricsRecorder(registry) : new NoOpMetricsRecorder(); + if (delegate != null) { + return delegate; + } + MeterRegistry registry = meterRegistryProvider.getIfAvailable(); + if (registry == null) { + return NO_OP; } + delegate = new MicrometerMetricsRecorder(registry); return delegate; } } diff --git a/logged-spring/src/main/java/com/fayupable/logged/spring/metrics/MicrometerMetricsRecorder.java b/logged-spring/src/main/java/com/fayupable/logged/spring/metrics/MicrometerMetricsRecorder.java index c73ccbe..86243a5 100644 --- a/logged-spring/src/main/java/com/fayupable/logged/spring/metrics/MicrometerMetricsRecorder.java +++ b/logged-spring/src/main/java/com/fayupable/logged/spring/metrics/MicrometerMetricsRecorder.java @@ -34,6 +34,15 @@ * prohibitively expensive, but it still allocates a {@code Meter.Id} and * performs a map lookup on every call; caching avoids repeating that work * on every single invocation of a hot {@code @Logged} method. + * + *

Cache keys are dedicated records ({@link InvocationCounterKey}, + * {@link DurationTimerKey}, {@link ErrorCounterKey}) rather than + * concatenated strings. {@code className} may be a fully qualified name + * (per {@link MetricsRecorder#record}'s contract), which can itself contain + * {@code '.'} characters; a string key built by joining fields with a + * separator could then theoretically collide between two different + * {@code (class, method, outcome)} triples. A record's {@code equals()} + * compares each field independently, so no such ambiguity is possible. */ public class MicrometerMetricsRecorder implements MetricsRecorder { @@ -45,9 +54,9 @@ public class MicrometerMetricsRecorder implements MetricsRecorder { private static final String ERROR_OUTCOME = "error"; private final MeterRegistry meterRegistry; - private final ConcurrentHashMap invocationCounters = new ConcurrentHashMap<>(); - private final ConcurrentHashMap durationTimers = new ConcurrentHashMap<>(); - private final ConcurrentHashMap errorCounters = new ConcurrentHashMap<>(); + private final ConcurrentHashMap invocationCounters = new ConcurrentHashMap<>(); + private final ConcurrentHashMap durationTimers = new ConcurrentHashMap<>(); + private final ConcurrentHashMap errorCounters = new ConcurrentHashMap<>(); public MicrometerMetricsRecorder(MeterRegistry meterRegistry) { this.meterRegistry = meterRegistry; @@ -81,29 +90,50 @@ public void record(String className, String methodName, long durationNanos, bool } private Counter invocationCounter(String className, String methodName, String outcome) { - String key = className + '.' + methodName + '.' + outcome; - return invocationCounters.computeIfAbsent(key, ignored -> Counter.builder(INVOCATIONS_METRIC) - .tag("class", className) - .tag("method", methodName) - .tag("outcome", outcome) + InvocationCounterKey key = new InvocationCounterKey(className, methodName, outcome); + return invocationCounters.computeIfAbsent(key, k -> Counter.builder(INVOCATIONS_METRIC) + .tag("class", k.className()) + .tag("method", k.methodName()) + .tag("outcome", k.outcome()) .register(meterRegistry)); } private Timer durationTimer(String className, String methodName) { - String key = className + '.' + methodName; - return durationTimers.computeIfAbsent(key, ignored -> Timer.builder(DURATION_METRIC) - .tag("class", className) - .tag("method", methodName) + DurationTimerKey key = new DurationTimerKey(className, methodName); + return durationTimers.computeIfAbsent(key, k -> Timer.builder(DURATION_METRIC) + .tag("class", k.className()) + .tag("method", k.methodName()) .publishPercentileHistogram() .register(meterRegistry)); } private Counter errorCounter(String className, String methodName, String exceptionType) { - String key = className + '.' + methodName + '.' + exceptionType; - return errorCounters.computeIfAbsent(key, ignored -> Counter.builder(ERRORS_METRIC) - .tag("class", className) - .tag("method", methodName) - .tag("exception", exceptionType) + ErrorCounterKey key = new ErrorCounterKey(className, methodName, exceptionType); + return errorCounters.computeIfAbsent(key, k -> Counter.builder(ERRORS_METRIC) + .tag("class", k.className()) + .tag("method", k.methodName()) + .tag("exception", k.exceptionType()) .register(meterRegistry)); } + + /** + * Identifies a single {@code method.invocations} counter by class, + * method, and outcome. + */ + private record InvocationCounterKey(String className, String methodName, String outcome) { + } + + /** + * Identifies a single {@code method.duration} timer by class and + * method. + */ + private record DurationTimerKey(String className, String methodName) { + } + + /** + * Identifies a single {@code method.errors} counter by class, method, + * and exception type. + */ + private record ErrorCounterKey(String className, String methodName, String exceptionType) { + } } diff --git a/logged-spring/src/main/java/com/fayupable/logged/spring/rabbitmq/RabbitTraceHeaderCarrier.java b/logged-spring/src/main/java/com/fayupable/logged/spring/rabbitmq/RabbitTraceHeaderCarrier.java new file mode 100644 index 0000000..ba4e506 --- /dev/null +++ b/logged-spring/src/main/java/com/fayupable/logged/spring/rabbitmq/RabbitTraceHeaderCarrier.java @@ -0,0 +1,121 @@ +package com.fayupable.logged.spring.rabbitmq; + +import com.fayupable.logged.core.model.FlowContext; +import com.fayupable.logged.spring.aspect.FlowContextCarrier; +import org.springframework.amqp.core.MessageProperties; + +import java.util.regex.Pattern; + +/** + * Carries a {@code @Logged} call chain's {@link FlowContext} across a + * RabbitMQ message, by writing it into the message's properties when + * publishing and reading it back when consuming. + * + *

The Spring AMQP counterpart to + * {@code com.fayupable.logged.spring.kafka.KafkaTraceHeaderCarrier}: the + * {@code traceId} and {@code depth} are written as plain entries in + * {@link MessageProperties#getHeaders()}, never into the message body. + * RabbitMQ message headers exist specifically for metadata like this: they + * travel with the message but are entirely separate from whatever + * serialization format the message body uses, so this never touches or + * constrains that body's schema. + * + *

Like every propagation class in this library, nothing here is wired in + * automatically. A consuming application calls {@link #writeToHeaders} when + * publishing a message and {@link #readAndAdopt} when consuming one, exactly + * where it already publishes or consumes RabbitMQ messages. + */ +public final class RabbitTraceHeaderCarrier { + + static final String TRACE_ID_HEADER = "logged-traceId"; + static final String DEPTH_HEADER = "logged-depth"; + + /** + * Matches every {@code traceId} this library can ever itself produce + * (see {@link com.fayupable.logged.core.model.FlowContext#root()}: up to + * sixteen hexadecimal characters) and nothing else. A RabbitMQ queue's + * publishers are typically other services within the same application's + * own trust boundary, unlike an HTTP endpoint that may be reachable from + * an untrusted caller, but validating here too costs nothing and keeps + * this carrier consistent with + * {@link com.fayupable.logged.spring.http.HttpTraceHeaderCarrier}. + */ + private static final Pattern VALID_TRACE_ID = Pattern.compile("[0-9a-fA-F]{1,16}"); + + private RabbitTraceHeaderCarrier() { + } + + /** + * Writes the current thread's {@link FlowContext}, if any is active, + * into {@code properties} as {@link #TRACE_ID_HEADER}/{@link #DEPTH_HEADER} + * header entries. + * + *

Does nothing if no {@code @Logged} call is currently active on this + * thread: a message published from outside any call chain simply + * carries no trace headers, exactly as if this method had never been + * called. + * + * @param properties the properties of the message about to be published + */ + public static void writeToHeaders(MessageProperties properties) { + FlowContext context = FlowContextCarrier.capture(); + if (context == null) { + return; + } + properties.setHeader(TRACE_ID_HEADER, context.traceId()); + properties.setHeader(DEPTH_HEADER, String.valueOf(context.depth())); + } + + /** + * Reads a {@link FlowContext} from {@code properties}, if present, + * adopts it as the active context on this thread for the duration of + * {@code work}, and restores this thread's previous context again + * afterward, regardless of whether {@code work} completes normally or + * throws. + * + *

If {@code properties} carries no {@link #TRACE_ID_HEADER} — for + * example, a message published by a service that does not use this + * library, or one published from outside any call chain — {@code work} + * is simply run as-is, with no context adopted. Any {@code @Logged} + * call made from within it then starts a new chain of its own, exactly + * as it would without this class involved at all. + * + * @param properties the properties of the message being consumed + * @param work the message-handling code to run with the message's + * trace context active + */ + public static void readAndAdopt(MessageProperties properties, Runnable work) { + FlowContext context = readContext(properties); + if (context == null) { + work.run(); + return; + } + + Runnable restorePreviousContext = FlowContextCarrier.adopt(context); + try { + work.run(); + } finally { + restorePreviousContext.run(); + } + } + + private static FlowContext readContext(MessageProperties properties) { + Object traceId = properties.getHeaders().get(TRACE_ID_HEADER); + if (!(traceId instanceof String traceIdString) || !VALID_TRACE_ID.matcher(traceIdString).matches()) { + return null; + } + return new FlowContext(traceIdString, readDepth(properties)); + } + + private static int readDepth(MessageProperties properties) { + Object depth = properties.getHeaders().get(DEPTH_HEADER); + if (!(depth instanceof String depthString)) { + return 0; + } + try { + return Integer.parseInt(depthString); + } catch (NumberFormatException malformedDepth) { + return 0; + } + } +} diff --git a/logged-spring/src/main/java/com/fayupable/logged/spring/security/RequestAttributesPropagatingExecutor.java b/logged-spring/src/main/java/com/fayupable/logged/spring/security/RequestAttributesPropagatingExecutor.java new file mode 100644 index 0000000..ae6c3fb --- /dev/null +++ b/logged-spring/src/main/java/com/fayupable/logged/spring/security/RequestAttributesPropagatingExecutor.java @@ -0,0 +1,74 @@ +package com.fayupable.logged.spring.security; + +import org.jspecify.annotations.NonNull; +import org.springframework.web.context.request.RequestAttributes; + +import java.util.Objects; +import java.util.concurrent.Executor; + +/** + * {@link Executor} decorator that carries the submitting thread's Spring Web + * {@link RequestAttributes} over to whatever thread actually runs the + * submitted task. + * + *

{@code com.fayupable.logged.spring.aspect.FlowContextPropagatingExecutor} + * solves the equivalent problem for this library's own call-chain tracking. + * That class deliberately does not also propagate {@link RequestAttributes}, + * so that it stays usable in applications with no Spring Web on the + * classpath at all. This class fills that specific gap for applications + * that do have Spring Web: without it, a nested {@code @Logged} call made + * from inside work submitted through a plain, unwrapped executor loses + * access to the current HTTP request entirely on the executor thread, and + * this library's IP-based caller identity resolution silently falls back to + * {@code "unknown"} for that nested call. + * + *

Wrap once, alongside {@code FlowContextPropagatingExecutor} if both are + * needed, by nesting decorators around the same delegate: + * + * 

{@code
+ * Executor propagating = new FlowContextPropagatingExecutor(
+ *         new RequestAttributesPropagatingExecutor(realExecutor));
+ * }
+ * + *

This class is deliberately not wired in automatically anywhere in this + * library's auto-configuration: a consuming application decides which + * executor should carry the current request across a thread hand-off, the + * same way it decides which methods get {@code @Logged} in the first place. + */ +public final class RequestAttributesPropagatingExecutor implements Executor { + + private final Executor delegate; + + /** + * Wraps {@code delegate} so that every task submitted through this + * executor carries the submitting thread's {@link RequestAttributes} + * into whichever thread {@code delegate} actually runs it on. + * + * @param delegate the executor that will actually run submitted tasks + */ + public RequestAttributesPropagatingExecutor(Executor delegate) { + this.delegate = Objects.requireNonNull(delegate, "delegate must not be null"); + } + + /** + * Captures the calling thread's current {@link RequestAttributes} and + * submits a wrapped task to the delegate executor that restores them + * before running {@code command} and restores the executor thread's own + * previous request attributes again afterward, regardless of whether + * {@code command} completes normally or throws. + * + * @param command the task to run + */ + @Override + public void execute(@NonNull Runnable command) { + RequestAttributes capturedAttributes = RequestAttributesPropagation.capture(); + delegate.execute(() -> { + Runnable restorePreviousAttributes = RequestAttributesPropagation.adopt(capturedAttributes); + try { + command.run(); + } finally { + restorePreviousAttributes.run(); + } + }); + } +} diff --git a/logged-spring/src/main/java/com/fayupable/logged/spring/security/RequestAttributesPropagation.java b/logged-spring/src/main/java/com/fayupable/logged/spring/security/RequestAttributesPropagation.java new file mode 100644 index 0000000..1958111 --- /dev/null +++ b/logged-spring/src/main/java/com/fayupable/logged/spring/security/RequestAttributesPropagation.java @@ -0,0 +1,60 @@ +package com.fayupable.logged.spring.security; + +import org.springframework.web.context.request.RequestAttributes; +import org.springframework.web.context.request.RequestContextHolder; + +/** + * Captures and restores the current thread's Spring Web {@link RequestAttributes} + * across a thread boundary, mirroring the {@code FlowContextHolder} + * {@code snapshot()}/{@code adopt()} pair in + * {@code com.fayupable.logged.spring.aspect} but for Spring's own + * request-scoped {@link ThreadLocal}, not this library's {@code FlowContext}. + * + *

{@link RequestContextHolder} stores the current {@link RequestAttributes} + * per thread. {@link RequestClientIpResolver} (and, through it, + * {@link HttpRequestClientInfoAdapter}/{@link SpringSecurityClientInfoAdapter}) + * reads from it to resolve a caller's IP address. Like this library's own + * {@code FlowContext}, this is invisible to any thread other than the one + * that set it, so a nested {@code @Logged} call made from inside work handed + * off to another thread cannot resolve a request-derived caller identity + * unless something first carries {@link RequestAttributes} across that + * boundary — which is exactly what this class exists to do, for + * {@link RequestAttributesPropagatingExecutor} and + * {@link RequestAttributesTaskDecorator}. + * + *

Package-private: this is an internal detail shared by those two + * classes, not part of this library's public API. + */ +final class RequestAttributesPropagation { + + private RequestAttributesPropagation() { + } + + /** + * Returns the {@link RequestAttributes} currently active on this + * thread, or {@code null} if there is no active HTTP request on this + * thread. + * + * @return the active request attributes, or {@code null} + */ + static RequestAttributes capture() { + return RequestContextHolder.getRequestAttributes(); + } + + /** + * Makes {@code attributes} the active {@link RequestAttributes} on the + * calling thread and returns a {@link Runnable} that undoes this, + * restoring whatever was active before this call. + * + * @param attributes the request attributes captured by {@link #capture()} + * on the thread that is handing off work, or + * {@code null} if that thread had none active + * @return a {@link Runnable} that restores this thread's previous + * request attributes; never {@code null} + */ + static Runnable adopt(RequestAttributes attributes) { + RequestAttributes previous = RequestContextHolder.getRequestAttributes(); + RequestContextHolder.setRequestAttributes(attributes); + return () -> RequestContextHolder.setRequestAttributes(previous); + } +} diff --git a/logged-spring/src/main/java/com/fayupable/logged/spring/security/RequestAttributesTaskDecorator.java b/logged-spring/src/main/java/com/fayupable/logged/spring/security/RequestAttributesTaskDecorator.java new file mode 100644 index 0000000..2efd395 --- /dev/null +++ b/logged-spring/src/main/java/com/fayupable/logged/spring/security/RequestAttributesTaskDecorator.java @@ -0,0 +1,60 @@ +package com.fayupable.logged.spring.security; + +import org.jspecify.annotations.NonNull; +import org.springframework.core.task.TaskDecorator; +import org.springframework.web.context.request.RequestAttributes; + +/** + * {@link TaskDecorator} that carries the submitting thread's Spring Web + * {@link RequestAttributes} into whatever thread Spring's {@code @Async} + * infrastructure actually runs the task on. + * + *

The Spring Web/Spring counterpart to + * {@code com.fayupable.logged.spring.aspect.FlowContextTaskDecorator}: that + * class carries this library's own call-chain tracking across an + * {@code @Async} boundary, this one carries the current HTTP request across + * the same boundary. Combine both on the same executor if both are needed: + * + * 

{@code
+ * @Bean
+ * public TaskExecutor taskExecutor() {
+ *     ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor();
+ *     executor.setTaskDecorator(runnable ->
+ *             new FlowContextTaskDecorator().decorate(
+ *                     new RequestAttributesTaskDecorator().decorate(runnable)));
+ *     executor.initialize();
+ *     return executor;
+ * }
+ * }
+ * + *

Without this registration, this library's IP-based caller identity + * resolution silently falls back to {@code "unknown"} for any nested + * {@code @Logged} call made from within an {@code @Async} method dispatched + * through the decorated executor. + */ +public final class RequestAttributesTaskDecorator implements TaskDecorator { + + /** + * Captures the calling thread's current {@link RequestAttributes} and + * returns a wrapped task that restores them before running + * {@code runnable} and restores the executor thread's own previous + * request attributes again afterward, regardless of whether + * {@code runnable} completes normally or throws. + * + * @param runnable the task Spring's {@code @Async} infrastructure is + * about to hand off to an executor thread + * @return a task carrying the calling thread's request attributes + */ + @Override + public Runnable decorate(@NonNull Runnable runnable) { + RequestAttributes capturedAttributes = RequestAttributesPropagation.capture(); + return () -> { + Runnable restorePreviousAttributes = RequestAttributesPropagation.adopt(capturedAttributes); + try { + runnable.run(); + } finally { + restorePreviousAttributes.run(); + } + }; + } +} diff --git a/logged-spring/src/main/java/com/fayupable/logged/spring/security/SecurityContextPropagatingExecutor.java b/logged-spring/src/main/java/com/fayupable/logged/spring/security/SecurityContextPropagatingExecutor.java new file mode 100644 index 0000000..18cfde2 --- /dev/null +++ b/logged-spring/src/main/java/com/fayupable/logged/spring/security/SecurityContextPropagatingExecutor.java @@ -0,0 +1,76 @@ +package com.fayupable.logged.spring.security; + +import org.jspecify.annotations.NonNull; +import org.springframework.security.core.context.SecurityContext; + +import java.util.Objects; +import java.util.concurrent.Executor; + +/** + * {@link Executor} decorator that carries the submitting thread's Spring + * Security {@link SecurityContext} over to whatever thread actually runs the + * submitted task. + * + *

{@code com.fayupable.logged.spring.aspect.FlowContextPropagatingExecutor} + * solves the equivalent problem for this library's own call-chain tracking. + * That class deliberately does not also propagate {@link SecurityContext}, + * so that it stays usable in applications with no Spring Security on the + * classpath at all. This class fills that specific gap for applications + * that do have Spring Security: without it, a nested {@code @Logged} call + * made from inside work submitted through a plain, unwrapped executor loses + * the authenticated user entirely on the executor thread, and this + * library's caller identity resolution silently falls back to an IP address + * or {@code "unknown"} for that nested call — losing *who* made the call, + * not just a secondary detail. + * + *

Wrap once, alongside {@code FlowContextPropagatingExecutor} if both are + * needed, by nesting decorators around the same delegate: + * + * 

{@code
+ * Executor propagating = new FlowContextPropagatingExecutor(
+ *         new SecurityContextPropagatingExecutor(realExecutor));
+ * }
+ * + *

This class is deliberately not wired in automatically anywhere in this + * library's auto-configuration: a consuming application decides which + * executor should carry the current authenticated user across a thread + * hand-off, the same way it decides which methods get {@code @Logged} in + * the first place. + */ +public final class SecurityContextPropagatingExecutor implements Executor { + + private final Executor delegate; + + /** + * Wraps {@code delegate} so that every task submitted through this + * executor carries the submitting thread's {@link SecurityContext} into + * whichever thread {@code delegate} actually runs it on. + * + * @param delegate the executor that will actually run submitted tasks + */ + public SecurityContextPropagatingExecutor(Executor delegate) { + this.delegate = Objects.requireNonNull(delegate, "delegate must not be null"); + } + + /** + * Captures the calling thread's current {@link SecurityContext} and + * submits a wrapped task to the delegate executor that restores it + * before running {@code command} and restores the executor thread's own + * previous security context again afterward, regardless of whether + * {@code command} completes normally or throws. + * + * @param command the task to run + */ + @Override + public void execute(@NonNull Runnable command) { + SecurityContext capturedContext = SecurityContextPropagation.capture(); + delegate.execute(() -> { + Runnable restorePreviousContext = SecurityContextPropagation.adopt(capturedContext); + try { + command.run(); + } finally { + restorePreviousContext.run(); + } + }); + } +} diff --git a/logged-spring/src/main/java/com/fayupable/logged/spring/security/SecurityContextPropagation.java b/logged-spring/src/main/java/com/fayupable/logged/spring/security/SecurityContextPropagation.java new file mode 100644 index 0000000..48b7c20 --- /dev/null +++ b/logged-spring/src/main/java/com/fayupable/logged/spring/security/SecurityContextPropagation.java @@ -0,0 +1,72 @@ +package com.fayupable.logged.spring.security; + +import org.springframework.security.core.context.SecurityContext; +import org.springframework.security.core.context.SecurityContextHolder; + +/** + * Captures and restores the current thread's Spring Security + * {@link SecurityContext} across a thread boundary, mirroring the + * {@code FlowContextHolder} {@code snapshot()}/{@code adopt()} pair in + * {@code com.fayupable.logged.spring.aspect} but for Spring Security's own + * {@link ThreadLocal}, not this library's {@code FlowContext}. + * + *

{@link SecurityContextHolder} defaults to + * {@code MODE_THREADLOCAL}, storing the current {@link SecurityContext} per + * thread. {@link SpringSecurityClientInfoAdapter} reads from it to resolve + * the authenticated caller's name. Like this library's own + * {@code FlowContext}, this is invisible to any thread other than the one + * that set it, so a nested {@code @Logged} call made from inside work handed + * off to another thread cannot resolve the authenticated user at all — it + * silently falls back to an IP address or {@code "unknown"} — unless + * something first carries {@link SecurityContext} across that boundary, + * which is exactly what this class exists to do, for + * {@link SecurityContextPropagatingExecutor} and + * {@link SecurityContextTaskDecorator}. + * + *

Package-private: this is an internal detail shared by those two + * classes, not part of this library's public API. + */ +final class SecurityContextPropagation { + + private SecurityContextPropagation() { + } + + /** + * Returns the {@link SecurityContext} currently active on this thread. + * + *

Unlike {@code FlowContextHolder.snapshot()} and + * {@code RequestAttributesPropagation.capture()}, this never returns + * {@code null}: {@link SecurityContextHolder#getContext()} itself lazily + * creates and stores an empty {@link SecurityContext} the first time it + * is called on a thread that has none, and returns that instead. + * + * @return the active security context; never {@code null} + */ + static SecurityContext capture() { + return SecurityContextHolder.getContext(); + } + + /** + * Makes {@code context} the active {@link SecurityContext} on the + * calling thread and returns a {@link Runnable} that undoes this, + * restoring whatever context was active before this call. + * + * @param context the security context captured by {@link #capture()} on + * the thread that is handing off work; if {@code null} + * is passed anyway, this thread's context is cleared + * rather than set to {@code null}, since + * {@link SecurityContextHolder} does not accept a + * {@code null} context + * @return a {@link Runnable} that restores this thread's previous + * security context; never {@code null} + */ + static Runnable adopt(SecurityContext context) { + SecurityContext previous = SecurityContextHolder.getContext(); + if (context == null) { + SecurityContextHolder.clearContext(); + } else { + SecurityContextHolder.setContext(context); + } + return () -> SecurityContextHolder.setContext(previous); + } +} diff --git a/logged-spring/src/main/java/com/fayupable/logged/spring/security/SecurityContextTaskDecorator.java b/logged-spring/src/main/java/com/fayupable/logged/spring/security/SecurityContextTaskDecorator.java new file mode 100644 index 0000000..cc449af --- /dev/null +++ b/logged-spring/src/main/java/com/fayupable/logged/spring/security/SecurityContextTaskDecorator.java @@ -0,0 +1,60 @@ +package com.fayupable.logged.spring.security; + +import org.jspecify.annotations.NonNull; +import org.springframework.core.task.TaskDecorator; +import org.springframework.security.core.context.SecurityContext; + +/** + * {@link TaskDecorator} that carries the submitting thread's Spring Security + * {@link SecurityContext} into whatever thread Spring's {@code @Async} + * infrastructure actually runs the task on. + * + *

The Spring Security counterpart to + * {@code com.fayupable.logged.spring.aspect.FlowContextTaskDecorator}: that + * class carries this library's own call-chain tracking across an + * {@code @Async} boundary, this one carries the authenticated user across + * the same boundary. Combine both on the same executor if both are needed: + * + * 

{@code
+ * @Bean
+ * public TaskExecutor taskExecutor() {
+ *     ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor();
+ *     executor.setTaskDecorator(runnable ->
+ *             new FlowContextTaskDecorator().decorate(
+ *                     new SecurityContextTaskDecorator().decorate(runnable)));
+ *     executor.initialize();
+ *     return executor;
+ * }
+ * }
+ * + *

Without this registration, this library's caller identity resolution + * silently falls back to an IP address or {@code "unknown"} for any nested + * {@code @Logged} call made from within an {@code @Async} method dispatched + * through the decorated executor, losing the authenticated user entirely. + */ +public final class SecurityContextTaskDecorator implements TaskDecorator { + + /** + * Captures the calling thread's current {@link SecurityContext} and + * returns a wrapped task that restores it before running + * {@code runnable} and restores the executor thread's own previous + * security context again afterward, regardless of whether + * {@code runnable} completes normally or throws. + * + * @param runnable the task Spring's {@code @Async} infrastructure is + * about to hand off to an executor thread + * @return a task carrying the calling thread's security context + */ + @Override + public Runnable decorate(@NonNull Runnable runnable) { + SecurityContext capturedContext = SecurityContextPropagation.capture(); + return () -> { + Runnable restorePreviousContext = SecurityContextPropagation.adopt(capturedContext); + try { + runnable.run(); + } finally { + restorePreviousContext.run(); + } + }; + } +} diff --git a/logged-spring/src/test/java/com/fayupable/logged/spring/aspect/EmissionPolicyTest.java b/logged-spring/src/test/java/com/fayupable/logged/spring/aspect/EmissionPolicyTest.java index e99c054..c8d4994 100644 --- a/logged-spring/src/test/java/com/fayupable/logged/spring/aspect/EmissionPolicyTest.java +++ b/logged-spring/src/test/java/com/fayupable/logged/spring/aspect/EmissionPolicyTest.java @@ -23,6 +23,12 @@ private static Method resolveMethod(long slowThresholdMs, double sampleRate) thr if (slowThresholdMs == 100 && sampleRate == 1.0) { return AnnotationHolder.class.getMethod("thresholdOneHundredAlwaysSampled"); } + if (slowThresholdMs == 100 && sampleRate == 2.0) { + return AnnotationHolder.class.getMethod("thresholdOneHundredOverSampled"); + } + if (slowThresholdMs == 100 && sampleRate == -0.5) { + return AnnotationHolder.class.getMethod("thresholdOneHundredNegativeSampled"); + } throw new IllegalArgumentException("No fixture method for " + slowThresholdMs + "/" + sampleRate); } @@ -90,6 +96,22 @@ void neverEmitsWhenSamplingDisabled() throws NoSuchMethodException { assertThat(EmissionPolicy.shouldEmit(logged, 1L, true)).isFalse(); } + + @Test + @DisplayName("clamps a sampleRate above 1.0 to behave as 'always sample'") + void clampsSampleRateAboveOne() throws NoSuchMethodException { + Logged logged = loggedWith(100, 2.0); + + assertThat(EmissionPolicy.shouldEmit(logged, 1L, true)).isTrue(); + } + + @Test + @DisplayName("clamps a negative sampleRate to behave as 'never sample'") + void clampsNegativeSampleRate() throws NoSuchMethodException { + Logged logged = loggedWith(100, -0.5); + + assertThat(EmissionPolicy.shouldEmit(logged, 1L, true)).isFalse(); + } } private interface AnnotationHolder { @@ -98,5 +120,11 @@ private interface AnnotationHolder { @Logged(slowThresholdMs = 100, sampleRate = 1.0) void thresholdOneHundredAlwaysSampled(); + + @Logged(slowThresholdMs = 100, sampleRate = 2.0) + void thresholdOneHundredOverSampled(); + + @Logged(slowThresholdMs = 100, sampleRate = -0.5) + void thresholdOneHundredNegativeSampled(); } } diff --git a/logged-spring/src/test/java/com/fayupable/logged/spring/aspect/FlowContextCarrierTest.java b/logged-spring/src/test/java/com/fayupable/logged/spring/aspect/FlowContextCarrierTest.java new file mode 100644 index 0000000..22ba43e --- /dev/null +++ b/logged-spring/src/test/java/com/fayupable/logged/spring/aspect/FlowContextCarrierTest.java @@ -0,0 +1,82 @@ +package com.fayupable.logged.spring.aspect; + +import com.fayupable.logged.core.model.FlowContext; +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("FlowContextCarrier") +class FlowContextCarrierTest { + + @Nested + @DisplayName("capture()") + class Capture { + + @Test + @DisplayName("returns null when no scope is active on this thread") + void returnsNullWhenNothingActive() { + assertThat(FlowContextCarrier.capture()).isNull(); + } + + @Test + @DisplayName("returns the same context FlowContextHolder.snapshot() would") + void matchesFlowContextHolderSnapshot() { + FlowContextHolder.FlowScope scope = FlowContextHolder.enter(); + try { + assertThat(FlowContextCarrier.capture()).isEqualTo(FlowContextHolder.snapshot()); + } finally { + scope.close(); + } + } + } + + @Nested + @DisplayName("adopt()") + class Adopt { + + @Test + @DisplayName("makes the given context active on this thread") + void makesContextActive() { + FlowContext context = new FlowContext("trace-xyz", 2); + + Runnable restore = FlowContextCarrier.adopt(context); + try { + assertThat(FlowContextCarrier.capture()).isEqualTo(context); + } finally { + restore.run(); + } + } + + @Test + @DisplayName("restores the previously active context once the returned Runnable is run") + void restoresPreviousContextOnRun() { + FlowContextHolder.FlowScope outer = FlowContextHolder.enter(); + try { + Runnable restore = FlowContextCarrier.adopt(new FlowContext("borrowed-trace", 9)); + restore.run(); + + assertThat(FlowContextCarrier.capture()).isEqualTo(outer.context()); + } finally { + outer.close(); + } + } + + @Test + @DisplayName("clears this thread's context when adopting null") + void clearsContextWhenAdoptingNull() { + FlowContextHolder.FlowScope outer = FlowContextHolder.enter(); + try { + Runnable restore = FlowContextCarrier.adopt(null); + try { + assertThat(FlowContextCarrier.capture()).isNull(); + } finally { + restore.run(); + } + } finally { + outer.close(); + } + } + } +} diff --git a/logged-spring/src/test/java/com/fayupable/logged/spring/aspect/FlowContextHolderTest.java b/logged-spring/src/test/java/com/fayupable/logged/spring/aspect/FlowContextHolderTest.java index b200888..29c2647 100644 --- a/logged-spring/src/test/java/com/fayupable/logged/spring/aspect/FlowContextHolderTest.java +++ b/logged-spring/src/test/java/com/fayupable/logged/spring/aspect/FlowContextHolderTest.java @@ -1,5 +1,6 @@ package com.fayupable.logged.spring.aspect; +import com.fayupable.logged.core.model.FlowContext; import org.junit.jupiter.api.DisplayName; import org.junit.jupiter.api.Nested; import org.junit.jupiter.api.Test; @@ -82,4 +83,103 @@ void restoresOuterContextAfterInnerScopeCloses() { } } } + + @Nested + @DisplayName("snapshot()") + class Snapshot { + + @Test + @DisplayName("returns null when no scope is active on this thread") + void returnsNullWhenNothingActive() { + assertThat(FlowContextHolder.snapshot()).isNull(); + } + + @Test + @DisplayName("returns the context of the innermost open scope") + void returnsInnermostContext() { + FlowContextHolder.FlowScope outer = FlowContextHolder.enter(); + try { + FlowContextHolder.FlowScope inner = FlowContextHolder.enter(); + try { + assertThat(FlowContextHolder.snapshot()).isEqualTo(inner.context()); + } finally { + inner.close(); + } + } finally { + outer.close(); + } + } + } + + @Nested + @DisplayName("adopt()") + class Adopt { + + @Test + @DisplayName("makes the given context active on this thread") + void makesContextActive() { + FlowContext context = new FlowContext("trace-xyz", 3); + + Runnable restore = FlowContextHolder.adopt(context); + try { + assertThat(FlowContextHolder.snapshot()).isEqualTo(context); + } finally { + restore.run(); + } + } + + @Test + @DisplayName("does not derive a deeper context, unlike enter()") + void doesNotIncrementDepth() { + FlowContext context = new FlowContext("trace-xyz", 3); + + Runnable restore = FlowContextHolder.adopt(context); + try { + assertThat(FlowContextHolder.snapshot().depth()).isEqualTo(3); + } finally { + restore.run(); + } + } + + @Test + @DisplayName("restores the previously active context once the returned Runnable is run") + void restoresPreviousContextOnRun() { + FlowContextHolder.FlowScope outer = FlowContextHolder.enter(); + try { + FlowContext adoptedContext = new FlowContext("borrowed-trace", 9); + Runnable restore = FlowContextHolder.adopt(adoptedContext); + restore.run(); + + assertThat(FlowContextHolder.snapshot()).isEqualTo(outer.context()); + } finally { + outer.close(); + } + } + + @Test + @DisplayName("clears the thread's context once the returned Runnable is run, when nothing was active before") + void clearsContextOnRunWhenNothingWasActiveBefore() { + FlowContext adoptedContext = new FlowContext("borrowed-trace", 9); + Runnable restore = FlowContextHolder.adopt(adoptedContext); + restore.run(); + + assertThat(FlowContextHolder.snapshot()).isNull(); + } + + @Test + @DisplayName("removes any active context when adopting null") + void removesContextWhenAdoptingNull() { + FlowContextHolder.FlowScope outer = FlowContextHolder.enter(); + try { + Runnable restore = FlowContextHolder.adopt(null); + try { + assertThat(FlowContextHolder.snapshot()).isNull(); + } finally { + restore.run(); + } + } finally { + outer.close(); + } + } + } } diff --git a/logged-spring/src/test/java/com/fayupable/logged/spring/aspect/FlowContextPropagatingExecutorTest.java b/logged-spring/src/test/java/com/fayupable/logged/spring/aspect/FlowContextPropagatingExecutorTest.java new file mode 100644 index 0000000..fbd312c --- /dev/null +++ b/logged-spring/src/test/java/com/fayupable/logged/spring/aspect/FlowContextPropagatingExecutorTest.java @@ -0,0 +1,269 @@ +package com.fayupable.logged.spring.aspect; + +import com.fayupable.logged.core.model.FlowContext; +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Nested; +import org.junit.jupiter.api.Test; +import org.slf4j.MDC; + +import java.util.concurrent.CountDownLatch; +import java.util.concurrent.ExecutorService; +import java.util.concurrent.Executors; +import java.util.concurrent.TimeUnit; +import java.util.concurrent.atomic.AtomicReference; + +import static org.assertj.core.api.Assertions.assertThat; +import static org.assertj.core.api.Assertions.assertThatThrownBy; + +@DisplayName("FlowContextPropagatingExecutor") +class FlowContextPropagatingExecutorTest { + + private ExecutorService delegate; + + @AfterEach + void tearDown() { + if (delegate != null) { + delegate.shutdownNow(); + } + MDC.clear(); + } + + /** + * Runs {@code command} on {@link #delegate} and blocks until it + * finishes, so assertions on the calling thread can rely on the + * submitted task having already run. + */ + private void executeAndAwait(FlowContextPropagatingExecutor executor, Runnable command) throws InterruptedException { + CountDownLatch latch = new CountDownLatch(1); + executor.execute(() -> { + try { + command.run(); + } finally { + latch.countDown(); + } + }); + assertThat(latch.await(5, TimeUnit.SECONDS)).as("submitted task completed in time").isTrue(); + } + + @Nested + @DisplayName("on a platform thread pool") + class OnPlatformThreadPool { + + @Test + @DisplayName("propagates the submitting thread's context onto the pool thread") + void propagatesContext() throws InterruptedException { + delegate = Executors.newFixedThreadPool(1); + FlowContextPropagatingExecutor executor = new FlowContextPropagatingExecutor(delegate); + AtomicReference observed = new AtomicReference<>(); + + FlowContextHolder.FlowScope scope = FlowContextHolder.enter(); + try { + FlowContext submitted = scope.context(); + executeAndAwait(executor, () -> observed.set(FlowContextHolder.snapshot())); + + assertThat(observed.get()).isEqualTo(submitted); + } finally { + scope.close(); + } + } + + @Test + @DisplayName("does not increase the depth of the propagated context") + void doesNotIncreaseDepth() throws InterruptedException { + delegate = Executors.newFixedThreadPool(1); + FlowContextPropagatingExecutor executor = new FlowContextPropagatingExecutor(delegate); + AtomicReference observedDepth = new AtomicReference<>(); + + FlowContextHolder.FlowScope outer = FlowContextHolder.enter(); + try { + FlowContextHolder.FlowScope inner = FlowContextHolder.enter(); + try { + executeAndAwait(executor, () -> observedDepth.set(FlowContextHolder.snapshot().depth())); + + assertThat(observedDepth.get()).isEqualTo(inner.context().depth()); + } finally { + inner.close(); + } + } finally { + outer.close(); + } + } + + @Test + @DisplayName("propagates null when nothing is active on the submitting thread") + void propagatesNullWhenNothingActive() throws InterruptedException { + delegate = Executors.newFixedThreadPool(1); + FlowContextPropagatingExecutor executor = new FlowContextPropagatingExecutor(delegate); + AtomicReference observed = new AtomicReference<>(FlowContext.root()); + + executeAndAwait(executor, () -> observed.set(FlowContextHolder.snapshot())); + + assertThat(observed.get()).isNull(); + } + + @Test + @DisplayName("propagates the submitting thread's MDC context map onto the pool thread") + void propagatesMdcContext() throws InterruptedException { + delegate = Executors.newFixedThreadPool(1); + FlowContextPropagatingExecutor executor = new FlowContextPropagatingExecutor(delegate); + AtomicReference observed = new AtomicReference<>(); + + MDC.put("requestId", "req-123"); + executeAndAwait(executor, () -> observed.set(MDC.get("requestId"))); + + assertThat(observed.get()).isEqualTo("req-123"); + } + + @Test + @DisplayName("does not leak a propagated MDC context into a later, unrelated task on a reused thread") + void doesNotLeakMdcBetweenTasks() throws InterruptedException { + delegate = Executors.newFixedThreadPool(1); + FlowContextPropagatingExecutor executor = new FlowContextPropagatingExecutor(delegate); + AtomicReference observedOnSecondTask = new AtomicReference<>("unset"); + + MDC.put("requestId", "req-123"); + executeAndAwait(executor, () -> { }); + MDC.clear(); + + executeAndAwait(executor, () -> observedOnSecondTask.set(MDC.get("requestId"))); + + assertThat(observedOnSecondTask.get()).isNull(); + } + + @Test + @DisplayName("truly restores the executor thread's own FlowContext, not merely masked by the next wrapped task's own adopt()") + void trulyRestoresFlowContextOnExecutorThread() throws InterruptedException { + delegate = Executors.newFixedThreadPool(1); + FlowContextPropagatingExecutor executor = new FlowContextPropagatingExecutor(delegate); + + FlowContextHolder.FlowScope scope = FlowContextHolder.enter(); + try { + executeAndAwait(executor, () -> { }); + } finally { + scope.close(); + } + + // Submitted straight to the raw delegate, bypassing this class's own + // adopt() call, so this observes whatever the previous wrapped task + // actually left behind on the reused pool thread. + AtomicReference observedWithoutWrapper = new AtomicReference<>(FlowContext.root()); + CountDownLatch latch = new CountDownLatch(1); + delegate.execute(() -> { + observedWithoutWrapper.set(FlowContextHolder.snapshot()); + latch.countDown(); + }); + assertThat(latch.await(5, TimeUnit.SECONDS)).isTrue(); + + assertThat(observedWithoutWrapper.get()).isNull(); + } + + @Test + @DisplayName("truly restores the executor thread's own MDC context, not merely masked by the next wrapped task's own adopt()") + void trulyRestoresMdcOnExecutorThread() throws InterruptedException { + delegate = Executors.newFixedThreadPool(1); + FlowContextPropagatingExecutor executor = new FlowContextPropagatingExecutor(delegate); + + MDC.put("requestId", "req-123"); + executeAndAwait(executor, () -> { }); + MDC.clear(); + + AtomicReference observedWithoutWrapper = new AtomicReference<>("unset"); + CountDownLatch latch = new CountDownLatch(1); + delegate.execute(() -> { + observedWithoutWrapper.set(MDC.get("requestId")); + latch.countDown(); + }); + assertThat(latch.await(5, TimeUnit.SECONDS)).isTrue(); + + assertThat(observedWithoutWrapper.get()).isNull(); + } + + @Test + @DisplayName("does not leak a propagated context into a later, unrelated task on a reused thread") + void doesNotLeakContextBetweenTasks() throws InterruptedException { + delegate = Executors.newFixedThreadPool(1); + FlowContextPropagatingExecutor executor = new FlowContextPropagatingExecutor(delegate); + AtomicReference observedOnSecondTask = new AtomicReference<>(FlowContext.root()); + + FlowContextHolder.FlowScope scope = FlowContextHolder.enter(); + try { + executeAndAwait(executor, () -> { }); + } finally { + scope.close(); + } + + executeAndAwait(executor, () -> observedOnSecondTask.set(FlowContextHolder.snapshot())); + + assertThat(observedOnSecondTask.get()).isNull(); + } + + @Test + @DisplayName("still restores the executor thread's context when the submitted task throws") + void restoresContextEvenWhenTaskThrows() throws InterruptedException { + delegate = Executors.newFixedThreadPool(1); + FlowContextPropagatingExecutor executor = new FlowContextPropagatingExecutor(delegate); + AtomicReference observedAfterFailure = new AtomicReference<>(FlowContext.root()); + + FlowContextHolder.FlowScope scope = FlowContextHolder.enter(); + try { + CountDownLatch latch = new CountDownLatch(1); + executor.execute(() -> { + try { + throw new IllegalStateException("boom"); + } finally { + latch.countDown(); + } + }); + assertThat(latch.await(5, TimeUnit.SECONDS)).isTrue(); + } finally { + scope.close(); + } + + executeAndAwait(executor, () -> observedAfterFailure.set(FlowContextHolder.snapshot())); + + assertThat(observedAfterFailure.get()).isNull(); + } + } + + @Nested + @DisplayName("on a virtual thread executor") + class OnVirtualThreadExecutor { + + @Test + @DisplayName("propagates the submitting thread's context onto the virtual thread") + void propagatesContext() throws InterruptedException { + delegate = Executors.newVirtualThreadPerTaskExecutor(); + FlowContextPropagatingExecutor executor = new FlowContextPropagatingExecutor(delegate); + AtomicReference observed = new AtomicReference<>(); + AtomicReference ranOnDifferentThread = new AtomicReference<>(); + Thread submittingThread = Thread.currentThread(); + + FlowContextHolder.FlowScope scope = FlowContextHolder.enter(); + try { + FlowContext submitted = scope.context(); + executeAndAwait(executor, () -> { + observed.set(FlowContextHolder.snapshot()); + ranOnDifferentThread.set(Thread.currentThread() != submittingThread); + }); + + assertThat(ranOnDifferentThread.get()).as("task ran on a different (virtual) thread").isTrue(); + assertThat(observed.get()).isEqualTo(submitted); + } finally { + scope.close(); + } + } + } + + @Nested + @DisplayName("constructor") + class Constructor { + + @Test + @DisplayName("rejects a null delegate") + void rejectsNullDelegate() { + assertThatThrownBy(() -> new FlowContextPropagatingExecutor(null)) + .isInstanceOf(NullPointerException.class); + } + } +} diff --git a/logged-spring/src/test/java/com/fayupable/logged/spring/aspect/FlowContextTaskDecoratorTest.java b/logged-spring/src/test/java/com/fayupable/logged/spring/aspect/FlowContextTaskDecoratorTest.java new file mode 100644 index 0000000..6a39b66 --- /dev/null +++ b/logged-spring/src/test/java/com/fayupable/logged/spring/aspect/FlowContextTaskDecoratorTest.java @@ -0,0 +1,208 @@ +package com.fayupable.logged.spring.aspect; + +import com.fayupable.logged.core.model.FlowContext; +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Nested; +import org.junit.jupiter.api.Test; +import org.slf4j.MDC; +import org.springframework.core.task.TaskDecorator; +import org.springframework.scheduling.concurrent.ThreadPoolTaskExecutor; + +import java.util.concurrent.CountDownLatch; +import java.util.concurrent.TimeUnit; +import java.util.concurrent.atomic.AtomicReference; + +import static org.assertj.core.api.Assertions.assertThat; + +@DisplayName("FlowContextTaskDecorator") +class FlowContextTaskDecoratorTest { + + private ThreadPoolTaskExecutor executor; + + @AfterEach + void tearDown() { + if (executor != null) { + executor.shutdown(); + } + MDC.clear(); + } + + private ThreadPoolTaskExecutor newDecoratedExecutor() { + ThreadPoolTaskExecutor taskExecutor = new ThreadPoolTaskExecutor(); + taskExecutor.setCorePoolSize(1); + taskExecutor.setMaxPoolSize(1); + taskExecutor.setTaskDecorator(new FlowContextTaskDecorator()); + taskExecutor.initialize(); + return taskExecutor; + } + + private void submitAndAwait(ThreadPoolTaskExecutor taskExecutor, Runnable command) throws InterruptedException { + CountDownLatch latch = new CountDownLatch(1); + taskExecutor.execute(() -> { + try { + command.run(); + } finally { + latch.countDown(); + } + }); + assertThat(latch.await(5, TimeUnit.SECONDS)).as("submitted task completed in time").isTrue(); + } + + @Nested + @DisplayName("as a Spring TaskExecutor's TaskDecorator") + class AsTaskExecutorDecorator { + + @Test + @DisplayName("propagates the submitting thread's context onto the executor thread") + void propagatesContext() throws InterruptedException { + executor = newDecoratedExecutor(); + AtomicReference observed = new AtomicReference<>(); + + FlowContextHolder.FlowScope scope = FlowContextHolder.enter(); + try { + FlowContext submitted = scope.context(); + submitAndAwait(executor, () -> observed.set(FlowContextHolder.snapshot())); + + assertThat(observed.get()).isEqualTo(submitted); + } finally { + scope.close(); + } + } + + @Test + @DisplayName("propagates null when nothing is active on the submitting thread") + void propagatesNullWhenNothingActive() throws InterruptedException { + executor = newDecoratedExecutor(); + AtomicReference observed = new AtomicReference<>(FlowContext.root()); + + submitAndAwait(executor, () -> observed.set(FlowContextHolder.snapshot())); + + assertThat(observed.get()).isNull(); + } + + @Test + @DisplayName("propagates the submitting thread's MDC context map onto the executor thread") + void propagatesMdcContext() throws InterruptedException { + executor = newDecoratedExecutor(); + AtomicReference observed = new AtomicReference<>(); + + MDC.put("requestId", "req-123"); + submitAndAwait(executor, () -> observed.set(MDC.get("requestId"))); + + assertThat(observed.get()).isEqualTo("req-123"); + } + + @Test + @DisplayName("does not leak a propagated MDC context into a later, unrelated task on a reused thread") + void doesNotLeakMdcBetweenTasks() throws InterruptedException { + executor = newDecoratedExecutor(); + AtomicReference observedOnSecondTask = new AtomicReference<>("unset"); + + MDC.put("requestId", "req-123"); + submitAndAwait(executor, () -> { }); + MDC.clear(); + + submitAndAwait(executor, () -> observedOnSecondTask.set(MDC.get("requestId"))); + + assertThat(observedOnSecondTask.get()).isNull(); + } + + @Test + @DisplayName("truly restores the executor thread's own FlowContext, not merely masked by the next wrapped task's own adopt()") + void trulyRestoresFlowContextOnExecutorThread() throws InterruptedException { + executor = newDecoratedExecutor(); + + FlowContextHolder.FlowScope scope = FlowContextHolder.enter(); + try { + submitAndAwait(executor, () -> { }); + } finally { + scope.close(); + } + + // Decorator removed so this probe observes the reused pool thread's + // raw leftover state, not a value freshly re-adopted by decorate(). + executor.setTaskDecorator(null); + AtomicReference observedWithoutDecoration = new AtomicReference<>(FlowContext.root()); + submitAndAwait(executor, () -> observedWithoutDecoration.set(FlowContextHolder.snapshot())); + + assertThat(observedWithoutDecoration.get()).isNull(); + } + + @Test + @DisplayName("truly restores the executor thread's own MDC context, not merely masked by the next wrapped task's own adopt()") + void trulyRestoresMdcOnExecutorThread() throws InterruptedException { + executor = newDecoratedExecutor(); + + MDC.put("requestId", "req-123"); + submitAndAwait(executor, () -> { }); + MDC.clear(); + + executor.setTaskDecorator(null); + AtomicReference observedWithoutDecoration = new AtomicReference<>("unset"); + submitAndAwait(executor, () -> observedWithoutDecoration.set(MDC.get("requestId"))); + + assertThat(observedWithoutDecoration.get()).isNull(); + } + + @Test + @DisplayName("does not leak a propagated context into a later, unrelated task on a reused thread") + void doesNotLeakContextBetweenTasks() throws InterruptedException { + executor = newDecoratedExecutor(); + AtomicReference observedOnSecondTask = new AtomicReference<>(FlowContext.root()); + + FlowContextHolder.FlowScope scope = FlowContextHolder.enter(); + try { + submitAndAwait(executor, () -> { }); + } finally { + scope.close(); + } + + submitAndAwait(executor, () -> observedOnSecondTask.set(FlowContextHolder.snapshot())); + + assertThat(observedOnSecondTask.get()).isNull(); + } + + @Test + @DisplayName("still restores the executor thread's context when the submitted task throws") + void restoresContextEvenWhenTaskThrows() throws InterruptedException { + executor = newDecoratedExecutor(); + AtomicReference observedAfterFailure = new AtomicReference<>(FlowContext.root()); + + FlowContextHolder.FlowScope scope = FlowContextHolder.enter(); + try { + CountDownLatch latch = new CountDownLatch(1); + executor.execute(() -> { + try { + throw new IllegalStateException("boom"); + } finally { + latch.countDown(); + } + }); + assertThat(latch.await(5, TimeUnit.SECONDS)).isTrue(); + } finally { + scope.close(); + } + + submitAndAwait(executor, () -> observedAfterFailure.set(FlowContextHolder.snapshot())); + + assertThat(observedAfterFailure.get()).isNull(); + } + } + + @Nested + @DisplayName("decorate()") + class Decorate { + + @Test + @DisplayName("returns a task that runs the original runnable") + void runsOriginalRunnable() { + TaskDecorator decorator = new FlowContextTaskDecorator(); + AtomicReference ran = new AtomicReference<>(false); + + decorator.decorate(() -> ran.set(true)).run(); + + assertThat(ran.get()).isTrue(); + } + } +} diff --git a/logged-spring/src/test/java/com/fayupable/logged/spring/aspect/LoggedAspectTest.java b/logged-spring/src/test/java/com/fayupable/logged/spring/aspect/LoggedAspectTest.java index d6806e6..7cdb6df 100644 --- a/logged-spring/src/test/java/com/fayupable/logged/spring/aspect/LoggedAspectTest.java +++ b/logged-spring/src/test/java/com/fayupable/logged/spring/aspect/LoggedAspectTest.java @@ -5,17 +5,23 @@ import com.fayupable.logged.core.port.IClientInfoPort; import com.fayupable.logged.core.port.InvocationEventEmitter; import com.fayupable.logged.core.port.MetricsRecorder; +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.junit.jupiter.params.ParameterizedTest; import org.junit.jupiter.params.provider.ValueSource; +import org.slf4j.MDC; import org.springframework.aop.aspectj.annotation.AspectJProxyFactory; import java.util.ArrayList; import java.util.Comparator; import java.util.List; +import java.util.concurrent.CompletableFuture; +import java.util.concurrent.CompletionException; +import java.util.concurrent.TimeUnit; +import java.util.concurrent.atomic.AtomicReference; import java.util.stream.Collectors; import static org.assertj.core.api.Assertions.assertThat; @@ -37,6 +43,11 @@ void setUp() { aspect = new LoggedAspect(eventEmitter, metricsRecorder, () -> CALLER_IDENTITY); } + @AfterEach + void tearDown() { + MDC.clear(); + } + private T proxy(T target) { AspectJProxyFactory factory = new AspectJProxyFactory(target); factory.addAspect(aspect); @@ -66,6 +77,18 @@ void emitsSuccessfulEvent() { assertThat(event.methodName()).isEqualTo("add"); } + @Test + @DisplayName("measures a plausible duration, not the sum of a nanoTime reading with itself") + void measuresAPlausibleDuration() { + Calculator calculator = proxy(new CalculatorImpl()); + + calculator.add(2, 3); + + long durationNanos = eventEmitter.events.get(0).durationNanos(); + assertThat(durationNanos).isPositive() + .isLessThan(TimeUnit.SECONDS.toNanos(5)); + } + @Test @DisplayName("resolves the caller identity through IClientInfoPort") void resolvesCallerIdentity() { @@ -115,6 +138,36 @@ void emitsFailedEvent() { assertThat(event.exceptionType()).isEqualTo("ArithmeticException"); } + @Test + @DisplayName("measures a plausible duration, not the sum of a nanoTime reading with itself") + void measuresAPlausibleDuration() { + Calculator calculator = proxy(new CalculatorImpl()); + + try { + calculator.divide(10, 0); + } catch (ArithmeticException ignored) { + // expected + } + + long durationNanos = eventEmitter.events.get(0).durationNanos(); + assertThat(durationNanos).isPositive() + .isLessThan(TimeUnit.SECONDS.toNanos(5)); + } + + @Test + @DisplayName("closes the flow scope on the calling thread even when the intercepted method throws") + void closesFlowScopeWhenMethodThrows() { + Calculator calculator = proxy(new CalculatorImpl()); + + try { + calculator.divide(10, 0); + } catch (ArithmeticException ignored) { + // expected + } + + assertThat(FlowContextHolder.snapshot()).isNull(); + } + @Test @DisplayName("never captures the exception message") void neverCapturesExceptionMessage() { @@ -132,6 +185,39 @@ void neverCapturesExceptionMessage() { assertThat(event.toString()).doesNotContain("by zero"); } + @Test + @DisplayName("reports the same root cause type as exception type when the exception has no cause") + void rootCauseEqualsExceptionTypeWhenNoCause() { + Calculator calculator = proxy(new CalculatorImpl()); + + try { + calculator.divide(10, 0); + } catch (ArithmeticException ignored) { + // expected + } + + MethodInvocationEvent event = eventEmitter.events.get(0); + + assertThat(event.rootCauseType()).isEqualTo(event.exceptionType()); + } + + @Test + @DisplayName("reports the deepest cause's type when the thrown exception wraps another exception") + void reportsDeepestCauseType() { + Calculator calculator = proxy(new WrappingCalculatorImpl()); + + try { + calculator.divide(10, 0); + } catch (IllegalStateException ignored) { + // expected + } + + MethodInvocationEvent event = eventEmitter.events.get(0); + + assertThat(event.exceptionType()).isEqualTo("IllegalStateException"); + assertThat(event.rootCauseType()).isEqualTo("ArithmeticException"); + } + @Test @DisplayName("still propagates the original exception to the caller") void propagatesException() { @@ -292,6 +378,192 @@ private ChainLink buildChain(int length) { } } + @Nested + @DisplayName("on a method returning CompletableFuture") + class OnCompletableFuture { + + @Test + @DisplayName("does not emit until the returned future actually completes") + void doesNotEmitBeforeCompletion() { + AsyncService service = proxy(new AsyncServiceImpl()); + CompletableFuture manuallyCompleted = new CompletableFuture<>(); + + service.manualAsync(manuallyCompleted); + + assertThat(eventEmitter.events).isEmpty(); + + manuallyCompleted.complete(99); + + assertThat(eventEmitter.events).hasSize(1); + } + + @Test + @DisplayName("closes the flow scope and clears the MDC synchronously, before the future even completes") + void closesFlowScopeAndMdcSynchronously() { + AsyncService service = proxy(new AsyncServiceImpl()); + CompletableFuture manuallyCompleted = new CompletableFuture<>(); + + service.manualAsync(manuallyCompleted); + + assertThat(FlowContextHolder.snapshot()) + .as("flow scope must already be closed on the calling thread, before the future completes") + .isNull(); + assertThat(MDC.get(LoggedMdcKeys.TRACE_ID)) + .as("MDC must already be cleared on the calling thread, before the future completes") + .isNull(); + + manuallyCompleted.complete(99); + } + + @Test + @DisplayName("emits success with a duration reflecting the real asynchronous work, not just submission") + void emitsSuccessAfterRealCompletion() throws Exception { + AsyncService service = proxy(new AsyncServiceImpl()); + + Integer value = service.computeAsync(21).get(5, TimeUnit.SECONDS); + + assertThat(value).isEqualTo(42); + assertThat(eventEmitter.events).hasSize(1); + MethodInvocationEvent event = eventEmitter.events.get(0); + System.out.println("ASYNC EVENT -> " + event); + assertThat(event.success()).isTrue(); + assertThat(event.durationNanos()).isGreaterThanOrEqualTo(TimeUnit.MILLISECONDS.toNanos(15)); + } + + @Test + @DisplayName("still returns the same value to the caller as an unadvised call would") + void returnsSameValueAsCaller() throws Exception { + AsyncService service = proxy(new AsyncServiceImpl()); + + Integer value = service.computeAsync(10).get(5, TimeUnit.SECONDS); + + assertThat(value).isEqualTo(20); + } + + @Test + @DisplayName("records a failure thrown directly by the async work") + void recordsDirectFailure() { + AsyncService service = proxy(new AsyncServiceImpl()); + + awaitCompletion(service.failDirectlyAsync()); + + assertThat(eventEmitter.events).hasSize(1); + MethodInvocationEvent event = eventEmitter.events.get(0); + System.out.println("ASYNC FAILURE EVENT -> " + event); + assertThat(event.success()).isFalse(); + assertThat(event.exceptionType()).isEqualTo("ArithmeticException"); + assertThat(event.rootCauseType()).isEqualTo("ArithmeticException"); + assertThat(event.durationNanos()).isPositive() + .isLessThan(TimeUnit.SECONDS.toNanos(5)); + } + + @Test + @DisplayName("unwraps CompletionException to report the actual exception thrown by a chained stage") + void unwrapsCompletionExceptionFromChainedStage() { + AsyncService service = proxy(new AsyncServiceImpl()); + + awaitCompletion(service.failWrappedAsync()); + + assertThat(eventEmitter.events).hasSize(1); + MethodInvocationEvent event = eventEmitter.events.get(0); + System.out.println("ASYNC WRAPPED FAILURE EVENT -> " + event); + assertThat(event.exceptionType()).isEqualTo("IllegalStateException"); + assertThat(event.rootCauseType()).isEqualTo("IllegalStateException"); + assertThat(event.exceptionType()).isNotEqualTo("CompletionException"); + } + + @Test + @DisplayName("still propagates the original failure to a caller waiting on the future") + void stillPropagatesFailureToCaller() { + AsyncService service = proxy(new AsyncServiceImpl()); + CompletableFuture future = service.failDirectlyAsync(); + + assertThatThrownBy(future::join) + .hasRootCauseInstanceOf(ArithmeticException.class); + } + + private void awaitCompletion(CompletableFuture future) { + try { + future.join(); + } catch (CompletionException ignored) { + // expected: we only need the future to have completed before asserting + } + } + } + + @Nested + @DisplayName("MDC propagation") + class MdcPropagationBehavior { + + @Test + @DisplayName("writes trace id, depth, class name, and method name for the duration of the call") + void writesMdcKeysDuringCall() { + MdcAwareServiceImpl service = new MdcAwareServiceImpl(); + MdcAwareService proxied = proxy(service); + + proxied.doWork(); + + MethodInvocationEvent event = eventEmitter.events.get(0); + assertThat(service.capturedTraceId.get()).isEqualTo(event.traceId()); + assertThat(service.capturedDepth.get()).isEqualTo(String.valueOf(event.depth())); + assertThat(service.capturedClassName.get()).isEqualTo(event.className()); + assertThat(service.capturedMethodName.get()).isEqualTo(event.methodName()); + } + + @Test + @DisplayName("clears the MDC once a root-level call returns") + void clearsMdcAfterRootCallReturns() { + MdcAwareService proxied = proxy(new MdcAwareServiceImpl()); + + proxied.doWork(); + + assertThat(MDC.get(LoggedMdcKeys.TRACE_ID)).isNull(); + assertThat(MDC.get(LoggedMdcKeys.CLASS_NAME)).isNull(); + } + + @Test + @DisplayName("restores the outer call's MDC values once a nested call returns") + void restoresOuterMdcValuesAfterNestedCallReturns() { + MdcNestedInnerImpl inner = new MdcNestedInnerImpl(); + MdcNestedOuterImpl outer = new MdcNestedOuterImpl(proxy(inner)); + MdcNestedOuter proxiedOuter = proxy(outer); + + proxiedOuter.outer(); + + assertThat(outer.depthDuringOuter.get()).isEqualTo("0"); + assertThat(inner.depthDuringInner.get()).isEqualTo("1"); + assertThat(outer.depthAfterInnerReturns.get()).isEqualTo("0"); + } + + @Test + @DisplayName("still clears the MDC when the intercepted method throws") + void clearsMdcWhenMethodThrows() { + Calculator calculator = proxy(new CalculatorImpl()); + + try { + calculator.divide(10, 0); + } catch (ArithmeticException ignored) { + // expected + } + + assertThat(MDC.get(LoggedMdcKeys.TRACE_ID)).isNull(); + assertThat(MDC.get(LoggedMdcKeys.CLASS_NAME)).isNull(); + } + + @Test + @DisplayName("does not touch the MDC at all when disabled") + void doesNotTouchMdcWhenDisabled() { + LoggedAspect mdcDisabledAspect = new LoggedAspect(eventEmitter, metricsRecorder, () -> CALLER_IDENTITY, false); + AspectJProxyFactory factory = new AspectJProxyFactory(new MdcAwareServiceImpl()); + factory.addAspect(mdcDisabledAspect); + MdcAwareService proxied = factory.getProxy(); + + proxied.doWork(); + + assertThat(MDC.getCopyOfContextMap()).isNull(); + } + } + @Nested @DisplayName("robustness against misbehaving observability collaborators") class Robustness { @@ -345,6 +617,40 @@ void returnsOriginalResultWhenMetricsRecorderThrows() { assertThat(calculator.add(2, 3)).isEqualTo(5); } + + @Test + @DisplayName("still restores the flow scope and MDC on this thread even when a collaborator throws an Error") + void restoresFlowScopeAndMdcWhenCollaboratorThrowsError() { + LoggedAspect faultyAspect = new LoggedAspect( + eventEmitter, + (className, methodName, durationNanos, success, exceptionType) -> { + throw new SimulatedObservabilityError("metrics backend crashed unrecoverably"); + }, + () -> CALLER_IDENTITY + ); + AspectJProxyFactory factory = new AspectJProxyFactory(new CalculatorImpl()); + factory.addAspect(faultyAspect); + Calculator calculator = factory.getProxy(); + + assertThatThrownBy(() -> calculator.add(2, 3)) + .isInstanceOf(SimulatedObservabilityError.class); + + assertThat(FlowContextHolder.snapshot()).isNull(); + assertThat(MDC.get(LoggedMdcKeys.TRACE_ID)).isNull(); + } + + /** + * Deliberately an {@link Error}, not a {@link RuntimeException}: + * {@code LoggedAspect} only catches {@code RuntimeException} inside + * {@code recordObservability}, by design, so this simulates the one + * category of collaborator failure that is expected to actually + * propagate past it. + */ + private static class SimulatedObservabilityError extends Error { + SimulatedObservabilityError(String message) { + super(message); + } + } } interface ChainLink { @@ -387,6 +693,24 @@ public int divide(int a, int b) { } } + static class WrappingCalculatorImpl implements Calculator { + @Logged(slowThresholdMs = 1000, sampleRate = 1.0) + @Override + public int add(int a, int b) { + return a + b; + } + + @Logged(slowThresholdMs = 1000, sampleRate = 1.0) + @Override + public int divide(int a, int b) { + try { + return a / b; + } catch (ArithmeticException cause) { + throw new IllegalStateException("calculation failed", cause); + } + } + } + static class SlowCalculatorImpl implements Calculator { @Logged(slowThresholdMs = 0, sampleRate = 0.0) @Override @@ -414,6 +738,110 @@ public int divide(int a, int b) { } } + interface AsyncService { + CompletableFuture computeAsync(int value); + + CompletableFuture failDirectlyAsync(); + + CompletableFuture failWrappedAsync(); + + CompletableFuture manualAsync(CompletableFuture future); + } + + static class AsyncServiceImpl implements AsyncService { + @Logged(slowThresholdMs = 1000, sampleRate = 1.0) + @Override + public CompletableFuture computeAsync(int value) { + return CompletableFuture.supplyAsync(() -> { + try { + Thread.sleep(20); + } catch (InterruptedException e) { + Thread.currentThread().interrupt(); + } + return value * 2; + }); + } + + @Logged(slowThresholdMs = 1000, sampleRate = 1.0) + @Override + public CompletableFuture failDirectlyAsync() { + return CompletableFuture.supplyAsync(() -> { + throw new ArithmeticException("boom"); + }); + } + + @Logged(slowThresholdMs = 1000, sampleRate = 1.0) + @Override + public CompletableFuture failWrappedAsync() { + return CompletableFuture.supplyAsync(() -> 10) + .thenApply(v -> { + throw new IllegalStateException("boom"); + }); + } + + @Logged(slowThresholdMs = 1000, sampleRate = 1.0) + @Override + public CompletableFuture manualAsync(CompletableFuture future) { + return future; + } + } + + interface MdcAwareService { + void doWork(); + } + + static class MdcAwareServiceImpl implements MdcAwareService { + final AtomicReference capturedTraceId = new AtomicReference<>(); + final AtomicReference capturedDepth = new AtomicReference<>(); + final AtomicReference capturedClassName = new AtomicReference<>(); + final AtomicReference capturedMethodName = new AtomicReference<>(); + + @Logged(slowThresholdMs = 1000, sampleRate = 1.0) + @Override + public void doWork() { + capturedTraceId.set(MDC.get(LoggedMdcKeys.TRACE_ID)); + capturedDepth.set(MDC.get(LoggedMdcKeys.DEPTH)); + capturedClassName.set(MDC.get(LoggedMdcKeys.CLASS_NAME)); + capturedMethodName.set(MDC.get(LoggedMdcKeys.METHOD_NAME)); + } + } + + interface MdcNestedOuter { + void outer(); + } + + interface MdcNestedInner { + void inner(); + } + + static class MdcNestedOuterImpl implements MdcNestedOuter { + private final MdcNestedInner inner; + final AtomicReference depthDuringOuter = new AtomicReference<>(); + final AtomicReference depthAfterInnerReturns = new AtomicReference<>(); + + MdcNestedOuterImpl(MdcNestedInner inner) { + this.inner = inner; + } + + @Logged(slowThresholdMs = 1000, sampleRate = 1.0) + @Override + public void outer() { + depthDuringOuter.set(MDC.get(LoggedMdcKeys.DEPTH)); + inner.inner(); + depthAfterInnerReturns.set(MDC.get(LoggedMdcKeys.DEPTH)); + } + } + + static class MdcNestedInnerImpl implements MdcNestedInner { + final AtomicReference depthDuringInner = new AtomicReference<>(); + + @Logged(slowThresholdMs = 1000, sampleRate = 1.0) + @Override + public void inner() { + depthDuringInner.set(MDC.get(LoggedMdcKeys.DEPTH)); + } + } + interface ServiceA { void process(); } @@ -464,7 +892,7 @@ static class RecordingMetricsRecorder implements MetricsRecorder { @Override public void record(String className, String methodName, long durationNanos, boolean success, String exceptionType) { MethodInvocationEvent recorded = new MethodInvocationEvent( - className, methodName, java.time.Instant.now(), durationNanos, success, exceptionType, "n/a", "n/a", -1 + className, methodName, java.time.Instant.now(), durationNanos, success, exceptionType, exceptionType, "n/a", "n/a", -1 ); recordings.add(recorded); System.out.println("METRIC -> " + recorded); diff --git a/logged-spring/src/test/java/com/fayupable/logged/spring/aspect/MdcContextPropagationTest.java b/logged-spring/src/test/java/com/fayupable/logged/spring/aspect/MdcContextPropagationTest.java new file mode 100644 index 0000000..a9c8dc5 --- /dev/null +++ b/logged-spring/src/test/java/com/fayupable/logged/spring/aspect/MdcContextPropagationTest.java @@ -0,0 +1,94 @@ +package com.fayupable.logged.spring.aspect; + +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Nested; +import org.junit.jupiter.api.Test; +import org.slf4j.MDC; + +import java.util.Map; + +import static org.assertj.core.api.Assertions.assertThat; + +@DisplayName("MdcContextPropagation") +class MdcContextPropagationTest { + + @AfterEach + void tearDown() { + MDC.clear(); + } + + @Nested + @DisplayName("capture()") + class Capture { + + @Test + @DisplayName("returns null when the MDC is empty") + void returnsNullWhenEmpty() { + assertThat(MdcContextPropagation.capture()).isNull(); + } + + @Test + @DisplayName("returns every entry currently in the MDC") + void returnsAllEntries() { + MDC.put("requestId", "req-123"); + MDC.put(LoggedMdcKeys.TRACE_ID, "trace-abc"); + + Map captured = MdcContextPropagation.capture(); + + assertThat(captured).containsEntry("requestId", "req-123") + .containsEntry(LoggedMdcKeys.TRACE_ID, "trace-abc"); + } + } + + @Nested + @DisplayName("adopt()") + class Adopt { + + @Test + @DisplayName("makes the given map the active MDC context") + void makesMapActive() { + Map context = Map.of("requestId", "req-999"); + + Runnable restore = MdcContextPropagation.adopt(context); + try { + assertThat(MDC.get("requestId")).isEqualTo("req-999"); + } finally { + restore.run(); + } + } + + @Test + @DisplayName("clears the MDC when adopting null") + void clearsMdcWhenAdoptingNull() { + MDC.put("requestId", "req-999"); + + Runnable restore = MdcContextPropagation.adopt(null); + try { + assertThat(MDC.getCopyOfContextMap()).isNull(); + } finally { + restore.run(); + } + } + + @Test + @DisplayName("restores the previously active map once the returned Runnable is run") + void restoresPreviousMapOnRun() { + MDC.put("requestId", "req-999"); + + Runnable restore = MdcContextPropagation.adopt(Map.of("requestId", "borrowed")); + restore.run(); + + assertThat(MDC.get("requestId")).isEqualTo("req-999"); + } + + @Test + @DisplayName("clears the MDC once the returned Runnable is run, when nothing was active before") + void clearsMdcOnRunWhenNothingWasActiveBefore() { + Runnable restore = MdcContextPropagation.adopt(Map.of("requestId", "borrowed")); + restore.run(); + + assertThat(MDC.getCopyOfContextMap()).isNull(); + } + } +} diff --git a/logged-spring/src/test/java/com/fayupable/logged/spring/aspect/MdcPropagationTest.java b/logged-spring/src/test/java/com/fayupable/logged/spring/aspect/MdcPropagationTest.java new file mode 100644 index 0000000..3188c4e --- /dev/null +++ b/logged-spring/src/test/java/com/fayupable/logged/spring/aspect/MdcPropagationTest.java @@ -0,0 +1,86 @@ +package com.fayupable.logged.spring.aspect; + +import com.fayupable.logged.core.model.FlowContext; +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Nested; +import org.junit.jupiter.api.Test; +import org.slf4j.MDC; + +import static org.assertj.core.api.Assertions.assertThat; + +@DisplayName("MdcPropagation") +class MdcPropagationTest { + + @AfterEach + void tearDown() { + MDC.clear(); + } + + @Nested + @DisplayName("push()") + class Push { + + @Test + @DisplayName("writes trace id, depth, class name, and method name under LoggedMdcKeys") + void writesAllKeys() { + FlowContext context = new FlowContext("trace-abc", 2); + + MdcPropagation.push(context, "OrderService", "placeOrder"); + + assertThat(MDC.get(LoggedMdcKeys.TRACE_ID)).isEqualTo("trace-abc"); + assertThat(MDC.get(LoggedMdcKeys.DEPTH)).isEqualTo("2"); + assertThat(MDC.get(LoggedMdcKeys.CLASS_NAME)).isEqualTo("OrderService"); + assertThat(MDC.get(LoggedMdcKeys.METHOD_NAME)).isEqualTo("placeOrder"); + } + } + + @Nested + @DisplayName("the Runnable returned by push()") + class Restore { + + @Test + @DisplayName("removes all keys when nothing was present before push()") + void removesKeysWhenNothingWasActiveBefore() { + FlowContext context = new FlowContext("trace-abc", 0); + + Runnable restore = MdcPropagation.push(context, "OrderService", "placeOrder"); + restore.run(); + + assertThat(MDC.get(LoggedMdcKeys.TRACE_ID)).isNull(); + assertThat(MDC.get(LoggedMdcKeys.DEPTH)).isNull(); + assertThat(MDC.get(LoggedMdcKeys.CLASS_NAME)).isNull(); + assertThat(MDC.get(LoggedMdcKeys.METHOD_NAME)).isNull(); + } + + @Test + @DisplayName("restores the outer call's values once a nested call's push() is undone") + void restoresOuterValuesAfterNestedCall() { + FlowContext outerContext = new FlowContext("outer-trace", 0); + Runnable restoreOuter = MdcPropagation.push(outerContext, "ServiceA", "process"); + + FlowContext innerContext = new FlowContext("outer-trace", 1); + Runnable restoreInner = MdcPropagation.push(innerContext, "ServiceB", "doWork"); + restoreInner.run(); + + assertThat(MDC.get(LoggedMdcKeys.DEPTH)).isEqualTo("0"); + assertThat(MDC.get(LoggedMdcKeys.CLASS_NAME)).isEqualTo("ServiceA"); + assertThat(MDC.get(LoggedMdcKeys.METHOD_NAME)).isEqualTo("process"); + + restoreOuter.run(); + assertThat(MDC.get(LoggedMdcKeys.CLASS_NAME)).isNull(); + } + + @Test + @DisplayName("does not disturb an unrelated MDC key the application set itself") + void doesNotDisturbUnrelatedKeys() { + MDC.put("requestId", "req-123"); + FlowContext context = new FlowContext("trace-abc", 0); + + Runnable restore = MdcPropagation.push(context, "OrderService", "placeOrder"); + restore.run(); + + assertThat(MDC.get("requestId")).isEqualTo("req-123"); + } + } +} diff --git a/logged-spring/src/test/java/com/fayupable/logged/spring/emitter/Slf4jInvocationEventEmitterTest.java b/logged-spring/src/test/java/com/fayupable/logged/spring/emitter/Slf4jInvocationEventEmitterTest.java index 283e5de..57d434e 100644 --- a/logged-spring/src/test/java/com/fayupable/logged/spring/emitter/Slf4jInvocationEventEmitterTest.java +++ b/logged-spring/src/test/java/com/fayupable/logged/spring/emitter/Slf4jInvocationEventEmitterTest.java @@ -42,13 +42,17 @@ void tearDown() { private MethodInvocationEvent successEvent(int depth) { return new MethodInvocationEvent( - "UserService", "getUser", Instant.now(), 12_000_000L, true, null, CALLER_IDENTITY, "abc123", depth + "UserService", "getUser", Instant.now(), 12_000_000L, true, null, null, CALLER_IDENTITY, "abc123", depth ); } private MethodInvocationEvent failureEvent(int depth) { + return failureEvent(depth, "IllegalArgumentException"); + } + + private MethodInvocationEvent failureEvent(int depth, String rootCauseType) { return new MethodInvocationEvent( - "UserService", "getUser", Instant.now(), 5_000_000L, false, "IllegalArgumentException", + "UserService", "getUser", Instant.now(), 5_000_000L, false, "IllegalArgumentException", rootCauseType, CALLER_IDENTITY, "abc123", depth ); } @@ -134,5 +138,27 @@ void includesExceptionType() { assertThat(message).contains("IllegalArgumentException"); } + + @Test + @DisplayName("omits root cause when it is the same type as the thrown exception") + void omitsRootCauseWhenSameAsExceptionType() { + emitter.emit(failureEvent(0, "IllegalArgumentException")); + + String message = printedMessage(); + + assertThat(message).doesNotContain("caused by"); + } + + @Test + @DisplayName("includes root cause when it differs from the thrown exception's type") + void includesRootCauseWhenItDiffers() { + emitter.emit(failureEvent(0, "SQLException")); + + String message = printedMessage(); + + assertThat(message) + .contains("IllegalArgumentException") + .contains("caused by SQLException"); + } } } diff --git a/logged-spring/src/test/java/com/fayupable/logged/spring/guard/LoggedTargetGuardBeanPostProcessorTest.java b/logged-spring/src/test/java/com/fayupable/logged/spring/guard/LoggedTargetGuardBeanPostProcessorTest.java index 1ffb4db..8b1d250 100644 --- a/logged-spring/src/test/java/com/fayupable/logged/spring/guard/LoggedTargetGuardBeanPostProcessorTest.java +++ b/logged-spring/src/test/java/com/fayupable/logged/spring/guard/LoggedTargetGuardBeanPostProcessorTest.java @@ -7,6 +7,10 @@ import org.junit.jupiter.api.Test; import org.springframework.stereotype.Repository; import org.springframework.stereotype.Service; +import reactor.core.publisher.Flux; +import reactor.core.publisher.Mono; + +import java.util.concurrent.CompletableFuture; import static org.assertj.core.api.Assertions.assertThat; import static org.assertj.core.api.Assertions.assertThatThrownBy; @@ -49,6 +53,14 @@ void rejectsLoggedMethod() { .isInstanceOf(IllegalStateException.class) .hasMessageContaining("AnnotatedRepositoryBean"); } + + @Test + @DisplayName("rejects a @Logged method inherited from an abstract base class, not just one declared directly") + void rejectsInheritedLoggedMethod() { + assertThatThrownBy(() -> guard.postProcessBeforeInitialization(new RepositoryWithInheritedLoggedMethod(), "repositoryWithInheritedLoggedMethod")) + .isInstanceOf(IllegalStateException.class) + .hasMessageContaining("RepositoryWithInheritedLoggedMethod"); + } } @Nested @@ -62,6 +74,14 @@ void rejectsLoggedMethod() { .isInstanceOf(IllegalStateException.class) .hasMessageContaining("CustomRepositoryImpl"); } + + @Test + @DisplayName("rejects a bean whose superclass, not the bean's own declared interfaces, implements the Spring Data repository interface") + void rejectsWhenInterfaceIsFoundViaSuperclassChain() { + assertThatThrownBy(() -> guard.postProcessBeforeInitialization(new DerivedCustomRepositoryImpl(), "derivedCustomRepositoryImpl")) + .isInstanceOf(IllegalStateException.class) + .hasMessageContaining("DerivedCustomRepositoryImpl"); + } } @Nested @@ -105,6 +125,36 @@ void allowsNonTrivialSuperclassChain() { } } + @Nested + @DisplayName("on a method returning a reactive Publisher") + class OnReactivePublisherReturnType { + + @Test + @DisplayName("rejects a @Logged method returning Mono") + void rejectsMonoReturnType() { + assertThatThrownBy(() -> guard.postProcessBeforeInitialization(new MonoReturningService(), "monoReturningService")) + .isInstanceOf(IllegalStateException.class) + .hasMessageContaining("MonoReturningService") + .hasMessageContaining("reactive publisher"); + } + + @Test + @DisplayName("rejects a @Logged method returning Flux") + void rejectsFluxReturnType() { + assertThatThrownBy(() -> guard.postProcessBeforeInitialization(new FluxReturningService(), "fluxReturningService")) + .isInstanceOf(IllegalStateException.class) + .hasMessageContaining("FluxReturningService") + .hasMessageContaining("reactive publisher"); + } + + @Test + @DisplayName("allows a @Logged method returning CompletableFuture") + void allowsCompletableFutureReturnType() { + assertThatCode(() -> guard.postProcessBeforeInitialization(new CompletableFutureReturningService(), "completableFutureReturningService")) + .doesNotThrowAnyException(); + } + } + @Entity static class AnnotatedEntity { @Logged @@ -125,6 +175,16 @@ public void findAll() { } } + static class BaseRepositoryWithLoggedMethod { + @Logged + public void save() { + } + } + + @Repository + static class RepositoryWithInheritedLoggedMethod extends BaseRepositoryWithLoggedMethod { + } + interface CustomRepository extends org.springframework.data.repository.Repository { } @@ -134,6 +194,9 @@ public void findAll() { } } + static class DerivedCustomRepositoryImpl extends CustomRepositoryImpl { + } + @Service static class PlainService { @Logged @@ -161,4 +224,25 @@ static class DerivedService extends BaseService { public void run() { } } + + static class MonoReturningService { + @Logged + public Mono getValue() { + return Mono.just("value"); + } + } + + static class FluxReturningService { + @Logged + public Flux getValues() { + return Flux.just("value"); + } + } + + static class CompletableFutureReturningService { + @Logged + public CompletableFuture getValue() { + return CompletableFuture.completedFuture("value"); + } + } } diff --git a/logged-spring/src/test/java/com/fayupable/logged/spring/http/FeignTraceRequestInterceptorTest.java b/logged-spring/src/test/java/com/fayupable/logged/spring/http/FeignTraceRequestInterceptorTest.java new file mode 100644 index 0000000..5860c4b --- /dev/null +++ b/logged-spring/src/test/java/com/fayupable/logged/spring/http/FeignTraceRequestInterceptorTest.java @@ -0,0 +1,47 @@ +package com.fayupable.logged.spring.http; + +import com.fayupable.logged.core.model.FlowContext; +import com.fayupable.logged.spring.aspect.FlowContextCarrier; +import feign.RequestTemplate; +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("FeignTraceRequestInterceptor") +class FeignTraceRequestInterceptorTest { + + private final FeignTraceRequestInterceptor interceptor = new FeignTraceRequestInterceptor(); + + @Nested + @DisplayName("apply()") + class Apply { + + @Test + @DisplayName("writes the active trace id and depth onto the outgoing Feign request template") + void writesActiveContextOntoTemplate() { + RequestTemplate template = new RequestTemplate(); + FlowContext active = new FlowContext("outer-trace", 2); + Runnable restore = FlowContextCarrier.adopt(active); + try { + interceptor.apply(template); + + assertThat(template.headers().get("X-Logged-Trace-Id")).containsExactly("outer-trace"); + assertThat(template.headers().get("X-Logged-Depth")).containsExactly("2"); + } finally { + restore.run(); + } + } + + @Test + @DisplayName("writes no trace headers when no call chain is active on this thread") + void writesNothingWhenNoContextActive() { + RequestTemplate template = new RequestTemplate(); + + interceptor.apply(template); + + assertThat(template.headers()).doesNotContainKey("X-Logged-Trace-Id"); + } + } +} diff --git a/logged-spring/src/test/java/com/fayupable/logged/spring/http/HttpTraceClientHttpRequestInterceptorTest.java b/logged-spring/src/test/java/com/fayupable/logged/spring/http/HttpTraceClientHttpRequestInterceptorTest.java new file mode 100644 index 0000000..ed59bde --- /dev/null +++ b/logged-spring/src/test/java/com/fayupable/logged/spring/http/HttpTraceClientHttpRequestInterceptorTest.java @@ -0,0 +1,84 @@ +package com.fayupable.logged.spring.http; + +import com.fayupable.logged.core.model.FlowContext; +import com.fayupable.logged.spring.aspect.FlowContextCarrier; +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Nested; +import org.junit.jupiter.api.Test; +import org.springframework.http.HttpMethod; +import org.springframework.http.HttpRequest; +import org.springframework.http.HttpHeaders; +import org.springframework.http.client.ClientHttpRequestExecution; +import org.springframework.http.client.ClientHttpResponse; +import org.springframework.mock.http.client.MockClientHttpRequest; +import org.springframework.mock.http.client.MockClientHttpResponse; + +import java.net.URI; +import java.util.concurrent.atomic.AtomicReference; + +import static org.assertj.core.api.Assertions.assertThat; + +@DisplayName("HttpTraceClientHttpRequestInterceptor") +class HttpTraceClientHttpRequestInterceptorTest { + + private final HttpTraceClientHttpRequestInterceptor interceptor = new HttpTraceClientHttpRequestInterceptor(); + + private final ClientHttpRequestExecution passthroughExecution = new ClientHttpRequestExecution() { + @Override + public ClientHttpResponse execute(HttpRequest request, byte[] body) { + return new MockClientHttpResponse(new byte[0], 200); + } + }; + + private HttpRequest newRequest() { + return new MockClientHttpRequest(HttpMethod.GET, URI.create("https://example.com/orders")); + } + + @Nested + @DisplayName("intercept()") + class Intercept { + + @Test + @DisplayName("writes the active trace id and depth onto the outgoing request's headers") + void writesActiveContextOntoRequest() throws Exception { + HttpRequest request = newRequest(); + FlowContext active = new FlowContext("outer-trace", 2); + Runnable restore = FlowContextCarrier.adopt(active); + try { + interceptor.intercept(request, new byte[0], passthroughExecution); + + HttpHeaders headers = request.getHeaders(); + assertThat(headers.getFirst("X-Logged-Trace-Id")).isEqualTo("outer-trace"); + assertThat(headers.getFirst("X-Logged-Depth")).isEqualTo("2"); + } finally { + restore.run(); + } + } + + @Test + @DisplayName("writes no trace headers when no call chain is active on this thread") + void writesNothingWhenNoContextActive() throws Exception { + HttpRequest request = newRequest(); + + interceptor.intercept(request, new byte[0], passthroughExecution); + + assertThat(request.getHeaders().getFirst("X-Logged-Trace-Id")).isNull(); + } + + @Test + @DisplayName("still delegates to the execution and returns its response") + void delegatesToExecution() throws Exception { + HttpRequest request = newRequest(); + AtomicReference executed = new AtomicReference<>(false); + ClientHttpRequestExecution execution = (req, body) -> { + executed.set(true); + return new MockClientHttpResponse(new byte[0], 200); + }; + + ClientHttpResponse response = interceptor.intercept(request, new byte[0], execution); + + assertThat(executed.get()).isTrue(); + assertThat(response.getStatusCode().value()).isEqualTo(200); + } + } +} diff --git a/logged-spring/src/test/java/com/fayupable/logged/spring/http/HttpTraceExchangeFilterFunctionTest.java b/logged-spring/src/test/java/com/fayupable/logged/spring/http/HttpTraceExchangeFilterFunctionTest.java new file mode 100644 index 0000000..6c50f9a --- /dev/null +++ b/logged-spring/src/test/java/com/fayupable/logged/spring/http/HttpTraceExchangeFilterFunctionTest.java @@ -0,0 +1,64 @@ +package com.fayupable.logged.spring.http; + +import com.fayupable.logged.core.model.FlowContext; +import com.fayupable.logged.spring.aspect.FlowContextCarrier; +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Nested; +import org.junit.jupiter.api.Test; +import org.springframework.http.HttpMethod; +import org.springframework.web.reactive.function.client.ClientRequest; +import org.springframework.web.reactive.function.client.ClientResponse; +import reactor.core.publisher.Mono; + +import java.net.URI; +import java.util.concurrent.atomic.AtomicReference; + +import static org.assertj.core.api.Assertions.assertThat; +import static org.mockito.Mockito.mock; + +@DisplayName("HttpTraceExchangeFilterFunction") +class HttpTraceExchangeFilterFunctionTest { + + private final HttpTraceExchangeFilterFunction filterFunction = new HttpTraceExchangeFilterFunction(); + + private ClientRequest newRequest() { + return ClientRequest.create(HttpMethod.GET, URI.create("https://example.com/orders")).build(); + } + + @Nested + @DisplayName("filter()") + class Filter { + + @Test + @DisplayName("writes the active trace id and depth onto the outgoing request's headers") + void writesActiveContextOntoRequest() { + AtomicReference observedRequest = new AtomicReference<>(); + FlowContext active = new FlowContext("outer-trace", 2); + Runnable restore = FlowContextCarrier.adopt(active); + try { + filterFunction.filter(newRequest(), request -> { + observedRequest.set(request); + return Mono.just(mock(ClientResponse.class)); + }).block(); + + assertThat(observedRequest.get().headers().getFirst("X-Logged-Trace-Id")).isEqualTo("outer-trace"); + assertThat(observedRequest.get().headers().getFirst("X-Logged-Depth")).isEqualTo("2"); + } finally { + restore.run(); + } + } + + @Test + @DisplayName("writes no trace headers when no call chain is active on this thread") + void writesNothingWhenNoContextActive() { + AtomicReference observedRequest = new AtomicReference<>(); + + filterFunction.filter(newRequest(), request -> { + observedRequest.set(request); + return Mono.just(mock(ClientResponse.class)); + }).block(); + + assertThat(observedRequest.get().headers().getFirst("X-Logged-Trace-Id")).isNull(); + } + } +} diff --git a/logged-spring/src/test/java/com/fayupable/logged/spring/http/HttpTraceHeaderCarrierTest.java b/logged-spring/src/test/java/com/fayupable/logged/spring/http/HttpTraceHeaderCarrierTest.java new file mode 100644 index 0000000..a578275 --- /dev/null +++ b/logged-spring/src/test/java/com/fayupable/logged/spring/http/HttpTraceHeaderCarrierTest.java @@ -0,0 +1,144 @@ +package com.fayupable.logged.spring.http; + +import com.fayupable.logged.core.model.FlowContext; +import com.fayupable.logged.spring.aspect.FlowContextCarrier; +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Nested; +import org.junit.jupiter.api.Test; + +import java.util.HashMap; +import java.util.Map; +import java.util.concurrent.atomic.AtomicReference; + +import static org.assertj.core.api.Assertions.assertThat; + +@DisplayName("HttpTraceHeaderCarrier") +class HttpTraceHeaderCarrierTest { + + @Nested + @DisplayName("writeToHeaders()") + class WriteToHeaders { + + @Test + @DisplayName("writes the active trace id and depth through the given header writer") + void writesActiveContext() { + Map headers = new HashMap<>(); + FlowContext active = new FlowContext("outer-trace", 2); + Runnable restore = FlowContextCarrier.adopt(active); + try { + HttpTraceHeaderCarrier.writeToHeaders(headers::put); + + assertThat(headers).containsEntry("X-Logged-Trace-Id", "outer-trace"); + assertThat(headers).containsEntry("X-Logged-Depth", "2"); + } finally { + restore.run(); + } + } + + @Test + @DisplayName("writes nothing when no call chain is active on this thread") + void writesNothingWhenNoContextActive() { + Map headers = new HashMap<>(); + + HttpTraceHeaderCarrier.writeToHeaders(headers::put); + + assertThat(headers).isEmpty(); + } + } + + @Nested + @DisplayName("readAndAdopt()") + class ReadAndAdopt { + + @Test + @DisplayName("adopts the trace id and depth read through the given header reader for the duration of the work") + void adoptsContextFromHeaders() { + Map headers = Map.of("X-Logged-Trace-Id", "abc123", "X-Logged-Depth", "3"); + AtomicReference observedTraceId = new AtomicReference<>(); + AtomicReference observedDepth = new AtomicReference<>(); + + HttpTraceHeaderCarrier.readAndAdopt(headers::get, () -> { + FlowContext active = FlowContextCarrier.capture(); + observedTraceId.set(active.traceId()); + observedDepth.set(active.depth()); + }); + + assertThat(observedTraceId.get()).isEqualTo("abc123"); + assertThat(observedDepth.get()).isEqualTo(3); + } + + @Test + @DisplayName("runs the work directly, adopting nothing, when no trace id header is present") + void runsWorkAsIsWhenNoTraceIdHeader() { + Map headers = Map.of(); + AtomicReference ran = new AtomicReference<>(false); + AtomicReference observedContext = new AtomicReference<>(new FlowContext("sentinel", 0)); + + HttpTraceHeaderCarrier.readAndAdopt(headers::get, () -> { + ran.set(true); + observedContext.set(FlowContextCarrier.capture()); + }); + + assertThat(ran.get()).isTrue(); + assertThat(observedContext.get()).isNull(); + } + + @Test + @DisplayName("runs the work directly, adopting nothing, when the trace id header does not look like a real trace id") + void runsWorkAsIsWhenTraceIdHeaderIsMalformed() { + Map headers = Map.of("X-Logged-Trace-Id", "abc123\n10:00:00 INFO FakeService - all clear"); + AtomicReference observedContext = new AtomicReference<>(new FlowContext("sentinel", 0)); + + HttpTraceHeaderCarrier.readAndAdopt(headers::get, () -> observedContext.set(FlowContextCarrier.capture())); + + assertThat(observedContext.get()).isNull(); + } + + @Test + @DisplayName("defaults depth to 0 when the depth header is missing") + void defaultsDepthToZeroWhenMissing() { + Map headers = Map.of("X-Logged-Trace-Id", "abc123"); + AtomicReference observedDepth = new AtomicReference<>(); + + HttpTraceHeaderCarrier.readAndAdopt(headers::get, () -> observedDepth.set(FlowContextCarrier.capture().depth())); + + assertThat(observedDepth.get()).isZero(); + } + + @Test + @DisplayName("restores this thread's previous context once the work completes") + void restoresPreviousContextAfterWork() { + Map headers = Map.of("X-Logged-Trace-Id", "abc123", "X-Logged-Depth", "1"); + FlowContext outerContext = new FlowContext("outer-trace", 5); + Runnable restoreOuter = FlowContextCarrier.adopt(outerContext); + try { + HttpTraceHeaderCarrier.readAndAdopt(headers::get, () -> { }); + + assertThat(FlowContextCarrier.capture()).isEqualTo(outerContext); + } finally { + restoreOuter.run(); + } + } + + @Test + @DisplayName("still restores this thread's previous context when the work throws") + void restoresPreviousContextWhenWorkThrows() { + Map headers = Map.of("X-Logged-Trace-Id", "abc123", "X-Logged-Depth", "1"); + FlowContext outerContext = new FlowContext("outer-trace", 5); + Runnable restoreOuter = FlowContextCarrier.adopt(outerContext); + try { + try { + HttpTraceHeaderCarrier.readAndAdopt(headers::get, () -> { + throw new IllegalStateException("boom"); + }); + } catch (IllegalStateException ignored) { + // expected + } + + assertThat(FlowContextCarrier.capture()).isEqualTo(outerContext); + } finally { + restoreOuter.run(); + } + } + } +} diff --git a/logged-spring/src/test/java/com/fayupable/logged/spring/http/HttpTraceServletFilterTest.java b/logged-spring/src/test/java/com/fayupable/logged/spring/http/HttpTraceServletFilterTest.java new file mode 100644 index 0000000..86400a6 --- /dev/null +++ b/logged-spring/src/test/java/com/fayupable/logged/spring/http/HttpTraceServletFilterTest.java @@ -0,0 +1,117 @@ +package com.fayupable.logged.spring.http; + +import com.fayupable.logged.core.model.FlowContext; +import com.fayupable.logged.spring.aspect.FlowContextCarrier; +import jakarta.servlet.FilterChain; +import jakarta.servlet.ServletException; +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Nested; +import org.junit.jupiter.api.Test; +import org.springframework.mock.web.MockHttpServletRequest; +import org.springframework.mock.web.MockHttpServletResponse; + +import java.io.IOException; +import java.util.concurrent.atomic.AtomicReference; + +import static org.assertj.core.api.Assertions.assertThat; +import static org.assertj.core.api.Assertions.assertThatThrownBy; + +@DisplayName("HttpTraceServletFilter") +class HttpTraceServletFilterTest { + + private final HttpTraceServletFilter filter = new HttpTraceServletFilter(); + + @Nested + @DisplayName("doFilterInternal()") + class DoFilterInternal { + + @Test + @DisplayName("adopts the trace id and depth carried by the incoming request's headers for the duration of the chain") + void adoptsContextFromRequestHeaders() throws ServletException, IOException { + MockHttpServletRequest request = new MockHttpServletRequest(); + request.addHeader("X-Logged-Trace-Id", "abc123"); + request.addHeader("X-Logged-Depth", "3"); + MockHttpServletResponse response = new MockHttpServletResponse(); + AtomicReference observedContext = new AtomicReference<>(); + FilterChain chain = (req, res) -> observedContext.set(FlowContextCarrier.capture()); + + filter.doFilter(request, response, chain); + + assertThat(observedContext.get()).isEqualTo(new FlowContext("abc123", 3)); + } + + @Test + @DisplayName("runs the chain directly, adopting nothing, when the request carries no trace id header") + void runsChainAsIsWhenNoTraceIdHeader() throws ServletException, IOException { + MockHttpServletRequest request = new MockHttpServletRequest(); + MockHttpServletResponse response = new MockHttpServletResponse(); + AtomicReference observedContext = new AtomicReference<>(new FlowContext("sentinel", 0)); + FilterChain chain = (req, res) -> observedContext.set(FlowContextCarrier.capture()); + + filter.doFilter(request, response, chain); + + assertThat(observedContext.get()).isNull(); + } + + @Test + @DisplayName("restores this thread's previous context once the chain completes") + void restoresPreviousContextAfterChain() throws ServletException, IOException { + MockHttpServletRequest request = new MockHttpServletRequest(); + request.addHeader("X-Logged-Trace-Id", "abc123"); + MockHttpServletResponse response = new MockHttpServletResponse(); + FlowContext outerContext = new FlowContext("outer-trace", 5); + Runnable restoreOuter = FlowContextCarrier.adopt(outerContext); + try { + filter.doFilter(request, response, (req, res) -> { }); + + assertThat(FlowContextCarrier.capture()).isEqualTo(outerContext); + } finally { + restoreOuter.run(); + } + } + + @Test + @DisplayName("propagates a ServletException thrown by the chain, and still restores this thread's previous context") + void propagatesServletExceptionAndRestoresContext() { + MockHttpServletRequest request = new MockHttpServletRequest(); + request.addHeader("X-Logged-Trace-Id", "abc123"); + MockHttpServletResponse response = new MockHttpServletResponse(); + FlowContext outerContext = new FlowContext("outer-trace", 5); + Runnable restoreOuter = FlowContextCarrier.adopt(outerContext); + try { + FilterChain chain = (req, res) -> { + throw new ServletException("boom"); + }; + + assertThatThrownBy(() -> filter.doFilter(request, response, chain)) + .isInstanceOf(ServletException.class) + .hasMessage("boom"); + assertThat(FlowContextCarrier.capture()).isEqualTo(outerContext); + } finally { + restoreOuter.run(); + } + } + + @Test + @DisplayName("propagates an IOException thrown by the chain, and still restores this thread's previous context") + void propagatesIoExceptionAndRestoresContext() { + MockHttpServletRequest request = new MockHttpServletRequest(); + request.addHeader("X-Logged-Trace-Id", "abc123"); + MockHttpServletResponse response = new MockHttpServletResponse(); + FlowContext outerContext = new FlowContext("outer-trace", 5); + Runnable restoreOuter = FlowContextCarrier.adopt(outerContext); + try { + FilterChain chain = (req, res) -> { + throw new IOException("boom"); + }; + + assertThatThrownBy(() -> filter.doFilter(request, response, chain)) + .isInstanceOf(IOException.class) + .hasMessage("boom"); + assertThat(FlowContextCarrier.capture()).isEqualTo(outerContext); + } finally { + restoreOuter.run(); + } + } + } +} diff --git a/logged-spring/src/test/java/com/fayupable/logged/spring/kafka/KafkaTraceHeaderCarrierTest.java b/logged-spring/src/test/java/com/fayupable/logged/spring/kafka/KafkaTraceHeaderCarrierTest.java new file mode 100644 index 0000000..f605bf0 --- /dev/null +++ b/logged-spring/src/test/java/com/fayupable/logged/spring/kafka/KafkaTraceHeaderCarrierTest.java @@ -0,0 +1,158 @@ +package com.fayupable.logged.spring.kafka; + +import com.fayupable.logged.core.model.FlowContext; +import com.fayupable.logged.spring.aspect.FlowContextCarrier; +import org.apache.kafka.common.header.internals.RecordHeaders; +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Nested; +import org.junit.jupiter.api.Test; + +import java.nio.charset.StandardCharsets; +import java.util.concurrent.atomic.AtomicReference; + +import static org.assertj.core.api.Assertions.assertThat; + +@DisplayName("KafkaTraceHeaderCarrier") +class KafkaTraceHeaderCarrierTest { + + @Nested + @DisplayName("writeToHeaders()") + class WriteToHeaders { + + @Test + @DisplayName("writes the active trace id and depth as headers") + void writesActiveContext() { + RecordHeaders headers = new RecordHeaders(); + FlowContext active = new FlowContext("outer-trace", 2); + Runnable restore = FlowContextCarrier.adopt(active); + try { + KafkaTraceHeaderCarrier.writeToHeaders(headers); + + String traceId = new String(headers.lastHeader("logged-traceId").value(), StandardCharsets.UTF_8); + String depth = new String(headers.lastHeader("logged-depth").value(), StandardCharsets.UTF_8); + + assertThat(traceId).isEqualTo("outer-trace"); + assertThat(depth).isEqualTo("2"); + } finally { + restore.run(); + } + } + + @Test + @DisplayName("writes nothing when no call chain is active on this thread") + void writesNothingWhenNoContextActive() { + RecordHeaders headers = new RecordHeaders(); + + KafkaTraceHeaderCarrier.writeToHeaders(headers); + + assertThat(headers.lastHeader("logged-traceId")).isNull(); + assertThat(headers.lastHeader("logged-depth")).isNull(); + } + } + + @Nested + @DisplayName("readAndAdopt()") + class ReadAndAdopt { + + @Test + @DisplayName("adopts the trace id and depth carried by the headers for the duration of the work") + void adoptsContextFromHeaders() { + RecordHeaders headers = new RecordHeaders(); + headers.add("logged-traceId", "abc123".getBytes(StandardCharsets.UTF_8)); + headers.add("logged-depth", "3".getBytes(StandardCharsets.UTF_8)); + AtomicReference observedTraceId = new AtomicReference<>(); + AtomicReference observedDepth = new AtomicReference<>(); + + KafkaTraceHeaderCarrier.readAndAdopt(headers, () -> { + FlowContext active = FlowContextCarrier.capture(); + observedTraceId.set(active.traceId()); + observedDepth.set(active.depth()); + }); + + assertThat(observedTraceId.get()).isEqualTo("abc123"); + assertThat(observedDepth.get()).isEqualTo(3); + } + + @Test + @DisplayName("runs the work directly, adopting nothing, when headers carry no trace id") + void runsWorkAsIsWhenNoTraceIdHeader() { + RecordHeaders headers = new RecordHeaders(); + AtomicReference ran = new AtomicReference<>(false); + AtomicReference observedContext = new AtomicReference<>(new FlowContext("sentinel", 0)); + + KafkaTraceHeaderCarrier.readAndAdopt(headers, () -> { + ran.set(true); + observedContext.set(FlowContextCarrier.capture()); + }); + + assertThat(ran.get()).isTrue(); + assertThat(observedContext.get()).isNull(); + } + + @Test + @DisplayName("runs the work directly, adopting nothing, when the trace id header does not look like a real trace id") + void runsWorkAsIsWhenTraceIdHeaderIsMalformed() { + RecordHeaders headers = new RecordHeaders(); + headers.add("logged-traceId", "abc123\n10:00:00 INFO FakeService - all clear".getBytes(StandardCharsets.UTF_8)); + AtomicReference observedContext = new AtomicReference<>(new FlowContext("sentinel", 0)); + + KafkaTraceHeaderCarrier.readAndAdopt(headers, () -> observedContext.set(FlowContextCarrier.capture())); + + assertThat(observedContext.get()).isNull(); + } + + @Test + @DisplayName("defaults depth to 0 when the depth header is missing") + void defaultsDepthToZeroWhenMissing() { + RecordHeaders headers = new RecordHeaders(); + headers.add("logged-traceId", "abc123".getBytes(StandardCharsets.UTF_8)); + AtomicReference observedDepth = new AtomicReference<>(); + + KafkaTraceHeaderCarrier.readAndAdopt(headers, () -> observedDepth.set(FlowContextCarrier.capture().depth())); + + assertThat(observedDepth.get()).isZero(); + } + + @Test + @DisplayName("restores this thread's previous context once the work completes") + void restoresPreviousContextAfterWork() { + RecordHeaders headers = new RecordHeaders(); + headers.add("logged-traceId", "abc123".getBytes(StandardCharsets.UTF_8)); + headers.add("logged-depth", "1".getBytes(StandardCharsets.UTF_8)); + + FlowContext outerContext = new FlowContext("outer-trace", 5); + Runnable restoreOuter = FlowContextCarrier.adopt(outerContext); + try { + KafkaTraceHeaderCarrier.readAndAdopt(headers, () -> { }); + + assertThat(FlowContextCarrier.capture()).isEqualTo(outerContext); + } finally { + restoreOuter.run(); + } + } + + @Test + @DisplayName("still restores this thread's previous context when the work throws") + void restoresPreviousContextWhenWorkThrows() { + RecordHeaders headers = new RecordHeaders(); + headers.add("logged-traceId", "abc123".getBytes(StandardCharsets.UTF_8)); + headers.add("logged-depth", "1".getBytes(StandardCharsets.UTF_8)); + + FlowContext outerContext = new FlowContext("outer-trace", 5); + Runnable restoreOuter = FlowContextCarrier.adopt(outerContext); + try { + try { + KafkaTraceHeaderCarrier.readAndAdopt(headers, () -> { + throw new IllegalStateException("boom"); + }); + } catch (IllegalStateException ignored) { + // expected + } + + assertThat(FlowContextCarrier.capture()).isEqualTo(outerContext); + } finally { + restoreOuter.run(); + } + } + } +} diff --git a/logged-spring/src/test/java/com/fayupable/logged/spring/metrics/LazyMetricsRecorderTest.java b/logged-spring/src/test/java/com/fayupable/logged/spring/metrics/LazyMetricsRecorderTest.java new file mode 100644 index 0000000..73407c5 --- /dev/null +++ b/logged-spring/src/test/java/com/fayupable/logged/spring/metrics/LazyMetricsRecorderTest.java @@ -0,0 +1,165 @@ +package com.fayupable.logged.spring.metrics; + +import io.micrometer.core.instrument.Counter; +import io.micrometer.core.instrument.MeterRegistry; +import io.micrometer.core.instrument.simple.SimpleMeterRegistry; +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Nested; +import org.junit.jupiter.api.Test; +import org.springframework.beans.factory.ObjectProvider; + +import java.util.concurrent.CountDownLatch; +import java.util.concurrent.ExecutorService; +import java.util.concurrent.Executors; +import java.util.concurrent.TimeUnit; + +import static org.assertj.core.api.Assertions.assertThat; + +@DisplayName("LazyMetricsRecorder") +class LazyMetricsRecorderTest { + + /** + * A test double whose {@link #getIfAvailable()} result can change + * between calls, simulating a {@link MeterRegistry} bean that does not + * exist yet at the moment of the first {@code @Logged} invocation and + * is only created afterward. + */ + private static final class SwitchableMeterRegistryProvider implements ObjectProvider { + private MeterRegistry registry; + + void becomeAvailable(MeterRegistry registry) { + this.registry = registry; + } + + @Override + public MeterRegistry getIfAvailable() { + return registry; + } + + @Override + public MeterRegistry getObject() { + throw new UnsupportedOperationException("not used by LazyMetricsRecorder"); + } + + @Override + public MeterRegistry getObject(Object... args) { + throw new UnsupportedOperationException("not used by LazyMetricsRecorder"); + } + } + + @Nested + @DisplayName("when a MeterRegistry is available from the first call") + class RegistryAvailableImmediately { + + @Test + @DisplayName("records through a real Micrometer-backed recorder") + void recordsThroughMicrometer() { + SimpleMeterRegistry meterRegistry = new SimpleMeterRegistry(); + SwitchableMeterRegistryProvider provider = new SwitchableMeterRegistryProvider(); + provider.becomeAvailable(meterRegistry); + LazyMetricsRecorder recorder = new LazyMetricsRecorder(provider); + + recorder.record("UserService", "getUser", 10_000_000L, true, null); + + Counter counter = meterRegistry.find("method.invocations") + .tag("class", "UserService").tag("method", "getUser").tag("outcome", "success") + .counter(); + assertThat(counter.count()).isEqualTo(1.0); + } + + @Test + @DisplayName("reuses the already-resolved recorder on a second call, without re-checking the ObjectProvider") + void reusesResolvedRecorderOnSecondCall() { + SimpleMeterRegistry meterRegistry = new SimpleMeterRegistry(); + SwitchableMeterRegistryProvider provider = new SwitchableMeterRegistryProvider(); + provider.becomeAvailable(meterRegistry); + LazyMetricsRecorder recorder = new LazyMetricsRecorder(provider); + + recorder.record("UserService", "getUser", 10_000_000L, true, null); + recorder.record("UserService", "getUser", 20_000_000L, true, null); + + Counter counter = meterRegistry.find("method.invocations") + .tag("class", "UserService").tag("method", "getUser").tag("outcome", "success") + .counter(); + assertThat(counter.count()).isEqualTo(2.0); + } + + @Test + @DisplayName("resolves exactly once under concurrent first access, with every thread's call recorded") + void resolvesSafelyUnderConcurrentFirstAccess() throws InterruptedException { + SimpleMeterRegistry meterRegistry = new SimpleMeterRegistry(); + SwitchableMeterRegistryProvider provider = new SwitchableMeterRegistryProvider(); + provider.becomeAvailable(meterRegistry); + LazyMetricsRecorder recorder = new LazyMetricsRecorder(provider); + + int threadCount = 20; + CountDownLatch readyLatch = new CountDownLatch(threadCount); + CountDownLatch startLatch = new CountDownLatch(1); + CountDownLatch doneLatch = new CountDownLatch(threadCount); + ExecutorService pool = Executors.newFixedThreadPool(threadCount); + try { + for (int i = 0; i < threadCount; i++) { + pool.execute(() -> { + readyLatch.countDown(); + try { + startLatch.await(5, TimeUnit.SECONDS); + recorder.record("UserService", "getUser", 1_000_000L, true, null); + } catch (InterruptedException e) { + Thread.currentThread().interrupt(); + } finally { + doneLatch.countDown(); + } + }); + } + + assertThat(readyLatch.await(5, TimeUnit.SECONDS)).as("all threads ready").isTrue(); + startLatch.countDown(); + assertThat(doneLatch.await(5, TimeUnit.SECONDS)).as("all threads finished").isTrue(); + } finally { + pool.shutdownNow(); + } + + Counter counter = meterRegistry.find("method.invocations") + .tag("class", "UserService").tag("method", "getUser").tag("outcome", "success") + .counter(); + assertThat(counter.count()).isEqualTo((double) threadCount); + } + } + + @Nested + @DisplayName("when no MeterRegistry is available yet") + class RegistryNotYetAvailable { + + @Test + @DisplayName("does not throw, falling back to a no-op recording") + void doesNotThrowWithoutRegistry() { + LazyMetricsRecorder recorder = new LazyMetricsRecorder(new SwitchableMeterRegistryProvider()); + + recorder.record("UserService", "getUser", 10_000_000L, true, null); + // No assertion beyond "did not throw": there is nowhere to observe + // a recording since no MeterRegistry exists yet. + } + + @Test + @DisplayName("does not permanently pin itself to no-op: once a MeterRegistry becomes available, later calls use it") + void recoversOnceRegistryBecomesAvailable() { + SwitchableMeterRegistryProvider provider = new SwitchableMeterRegistryProvider(); + LazyMetricsRecorder recorder = new LazyMetricsRecorder(provider); + + // First call races ahead of the MeterRegistry bean's own creation. + recorder.record("UserService", "getUser", 10_000_000L, true, null); + + SimpleMeterRegistry meterRegistry = new SimpleMeterRegistry(); + provider.becomeAvailable(meterRegistry); + + recorder.record("UserService", "getUser", 20_000_000L, true, null); + + Counter counter = meterRegistry.find("method.invocations") + .tag("class", "UserService").tag("method", "getUser").tag("outcome", "success") + .counter(); + assertThat(counter.count()) + .as("the call made after the registry became available must have been recorded") + .isEqualTo(1.0); + } + } +} diff --git a/logged-spring/src/test/java/com/fayupable/logged/spring/metrics/MicrometerMetricsRecorderTest.java b/logged-spring/src/test/java/com/fayupable/logged/spring/metrics/MicrometerMetricsRecorderTest.java index 5909b0b..dbdcad6 100644 --- a/logged-spring/src/test/java/com/fayupable/logged/spring/metrics/MicrometerMetricsRecorderTest.java +++ b/logged-spring/src/test/java/com/fayupable/logged/spring/metrics/MicrometerMetricsRecorderTest.java @@ -133,5 +133,26 @@ void accumulatesSameMeters() { assertThat(invocationCounter.count()).isEqualTo(2.0); assertThat(timer.count()).isEqualTo(3L); } + + @Test + @DisplayName("does not conflate two different (class, method) pairs whose fully qualified names share a dot boundary") + void doesNotConflateAmbiguousFullyQualifiedNames() { + recorder.record("com.example", "FooBar", 10_000_000L, true, null); + recorder.record("com.example.FooBar", "unrelated", 20_000_000L, true, null); + + Counter firstCounter = meterRegistry.find("method.invocations") + .tag("class", "com.example") + .tag("method", "FooBar") + .tag("outcome", "success") + .counter(); + Counter secondCounter = meterRegistry.find("method.invocations") + .tag("class", "com.example.FooBar") + .tag("method", "unrelated") + .tag("outcome", "success") + .counter(); + + assertThat(firstCounter.count()).isEqualTo(1.0); + assertThat(secondCounter.count()).isEqualTo(1.0); + } } } diff --git a/logged-spring/src/test/java/com/fayupable/logged/spring/rabbitmq/RabbitTraceHeaderCarrierTest.java b/logged-spring/src/test/java/com/fayupable/logged/spring/rabbitmq/RabbitTraceHeaderCarrierTest.java new file mode 100644 index 0000000..c4101a1 --- /dev/null +++ b/logged-spring/src/test/java/com/fayupable/logged/spring/rabbitmq/RabbitTraceHeaderCarrierTest.java @@ -0,0 +1,153 @@ +package com.fayupable.logged.spring.rabbitmq; + +import com.fayupable.logged.core.model.FlowContext; +import com.fayupable.logged.spring.aspect.FlowContextCarrier; +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Nested; +import org.junit.jupiter.api.Test; +import org.springframework.amqp.core.MessageProperties; + +import java.util.concurrent.atomic.AtomicReference; + +import static org.assertj.core.api.Assertions.assertThat; + +@DisplayName("RabbitTraceHeaderCarrier") +class RabbitTraceHeaderCarrierTest { + + @Nested + @DisplayName("writeToHeaders()") + class WriteToHeaders { + + @Test + @DisplayName("writes the active trace id and depth as headers") + void writesActiveContext() { + MessageProperties properties = new MessageProperties(); + FlowContext active = new FlowContext("outer-trace", 2); + Runnable restore = FlowContextCarrier.adopt(active); + try { + RabbitTraceHeaderCarrier.writeToHeaders(properties); + + assertThat(properties.getHeaders().get("logged-traceId")).isEqualTo("outer-trace"); + assertThat(properties.getHeaders().get("logged-depth")).isEqualTo("2"); + } finally { + restore.run(); + } + } + + @Test + @DisplayName("writes nothing when no call chain is active on this thread") + void writesNothingWhenNoContextActive() { + MessageProperties properties = new MessageProperties(); + + RabbitTraceHeaderCarrier.writeToHeaders(properties); + + assertThat(properties.getHeaders()).doesNotContainKeys("logged-traceId", "logged-depth"); + } + } + + @Nested + @DisplayName("readAndAdopt()") + class ReadAndAdopt { + + @Test + @DisplayName("adopts the trace id and depth carried by the headers for the duration of the work") + void adoptsContextFromHeaders() { + MessageProperties properties = new MessageProperties(); + properties.setHeader("logged-traceId", "abc123"); + properties.setHeader("logged-depth", "3"); + AtomicReference observedTraceId = new AtomicReference<>(); + AtomicReference observedDepth = new AtomicReference<>(); + + RabbitTraceHeaderCarrier.readAndAdopt(properties, () -> { + FlowContext active = FlowContextCarrier.capture(); + observedTraceId.set(active.traceId()); + observedDepth.set(active.depth()); + }); + + assertThat(observedTraceId.get()).isEqualTo("abc123"); + assertThat(observedDepth.get()).isEqualTo(3); + } + + @Test + @DisplayName("runs the work directly, adopting nothing, when headers carry no trace id") + void runsWorkAsIsWhenNoTraceIdHeader() { + MessageProperties properties = new MessageProperties(); + AtomicReference ran = new AtomicReference<>(false); + AtomicReference observedContext = new AtomicReference<>(new FlowContext("sentinel", 0)); + + RabbitTraceHeaderCarrier.readAndAdopt(properties, () -> { + ran.set(true); + observedContext.set(FlowContextCarrier.capture()); + }); + + assertThat(ran.get()).isTrue(); + assertThat(observedContext.get()).isNull(); + } + + @Test + @DisplayName("runs the work directly, adopting nothing, when the trace id header does not look like a real trace id") + void runsWorkAsIsWhenTraceIdHeaderIsMalformed() { + MessageProperties properties = new MessageProperties(); + properties.setHeader("logged-traceId", "abc123\n10:00:00 INFO FakeService - all clear"); + AtomicReference observedContext = new AtomicReference<>(new FlowContext("sentinel", 0)); + + RabbitTraceHeaderCarrier.readAndAdopt(properties, () -> observedContext.set(FlowContextCarrier.capture())); + + assertThat(observedContext.get()).isNull(); + } + + @Test + @DisplayName("defaults depth to 0 when the depth header is missing") + void defaultsDepthToZeroWhenMissing() { + MessageProperties properties = new MessageProperties(); + properties.setHeader("logged-traceId", "abc123"); + AtomicReference observedDepth = new AtomicReference<>(); + + RabbitTraceHeaderCarrier.readAndAdopt(properties, () -> observedDepth.set(FlowContextCarrier.capture().depth())); + + assertThat(observedDepth.get()).isZero(); + } + + @Test + @DisplayName("restores this thread's previous context once the work completes") + void restoresPreviousContextAfterWork() { + MessageProperties properties = new MessageProperties(); + properties.setHeader("logged-traceId", "abc123"); + properties.setHeader("logged-depth", "1"); + + FlowContext outerContext = new FlowContext("outer-trace", 5); + Runnable restoreOuter = FlowContextCarrier.adopt(outerContext); + try { + RabbitTraceHeaderCarrier.readAndAdopt(properties, () -> { }); + + assertThat(FlowContextCarrier.capture()).isEqualTo(outerContext); + } finally { + restoreOuter.run(); + } + } + + @Test + @DisplayName("still restores this thread's previous context when the work throws") + void restoresPreviousContextWhenWorkThrows() { + MessageProperties properties = new MessageProperties(); + properties.setHeader("logged-traceId", "abc123"); + properties.setHeader("logged-depth", "1"); + + FlowContext outerContext = new FlowContext("outer-trace", 5); + Runnable restoreOuter = FlowContextCarrier.adopt(outerContext); + try { + try { + RabbitTraceHeaderCarrier.readAndAdopt(properties, () -> { + throw new IllegalStateException("boom"); + }); + } catch (IllegalStateException ignored) { + // expected + } + + assertThat(FlowContextCarrier.capture()).isEqualTo(outerContext); + } finally { + restoreOuter.run(); + } + } + } +} diff --git a/logged-spring/src/test/java/com/fayupable/logged/spring/security/NestedAsyncCallerIdentityDemoTest.java b/logged-spring/src/test/java/com/fayupable/logged/spring/security/NestedAsyncCallerIdentityDemoTest.java new file mode 100644 index 0000000..261ec1b --- /dev/null +++ b/logged-spring/src/test/java/com/fayupable/logged/spring/security/NestedAsyncCallerIdentityDemoTest.java @@ -0,0 +1,147 @@ +package com.fayupable.logged.spring.security; + +import com.fayupable.logged.core.annotation.Logged; +import com.fayupable.logged.core.model.MethodInvocationEvent; +import com.fayupable.logged.core.port.InvocationEventEmitter; +import com.fayupable.logged.core.port.MetricsRecorder; +import com.fayupable.logged.spring.aspect.LoggedAspect; +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Test; +import org.springframework.aop.aspectj.annotation.AspectJProxyFactory; +import org.springframework.security.authentication.UsernamePasswordAuthenticationToken; +import org.springframework.security.core.GrantedAuthority; +import org.springframework.security.core.authority.SimpleGrantedAuthority; +import org.springframework.security.core.context.SecurityContextHolder; + +import java.util.ArrayList; +import java.util.List; +import java.util.concurrent.CountDownLatch; +import java.util.concurrent.ExecutorService; +import java.util.concurrent.Executors; +import java.util.concurrent.TimeUnit; +import java.util.concurrent.Executor; + +import static org.assertj.core.api.Assertions.assertThat; + +/** + * Demonstrates, with real emitted events printed to the console, the exact + * gap {@link SecurityContextPropagatingExecutor} closes: a nested + * {@code @Logged} call dispatched through a plain, unwrapped {@link Executor} + * loses the authenticated caller entirely on the executor thread, even + * though nothing else about the call is wrong. + */ +@DisplayName("Nested async caller identity propagation (demo)") +class NestedAsyncCallerIdentityDemoTest { + + private final List events = new ArrayList<>(); + private ExecutorService rawExecutor; + + @AfterEach + void tearDown() { + SecurityContextHolder.clearContext(); + if (rawExecutor != null) { + rawExecutor.shutdownNow(); + } + } + + private LoggedAspect newAspect() { + InvocationEventEmitter emitter = event -> { + events.add(event); + System.out.println("EMITTED -> " + event); + }; + MetricsRecorder metricsRecorder = (className, methodName, durationNanos, success, exceptionType) -> { }; + return new LoggedAspect(emitter, metricsRecorder, new SpringSecurityClientInfoAdapter(false)); + } + + private T proxy(T target, LoggedAspect aspect) { + AspectJProxyFactory factory = new AspectJProxyFactory(target); + factory.addAspect(aspect); + return factory.getProxy(); + } + + private void authenticateAs(String username) { + List authorities = List.of(new SimpleGrantedAuthority("ROLE_USER")); + SecurityContextHolder.getContext().setAuthentication( + new UsernamePasswordAuthenticationToken(username, "password", authorities)); + } + + interface InnerService { + void doWork(); + } + + static class InnerServiceImpl implements InnerService { + @Logged(sampleRate = 1.0) + @Override + public void doWork() { + // no-op: only the call itself matters for this demo + } + } + + interface OuterService { + void process(Executor executor) throws InterruptedException; + } + + static class OuterServiceImpl implements OuterService { + private final InnerService inner; + private final CountDownLatch innerCallFinished; + + OuterServiceImpl(InnerService inner, CountDownLatch innerCallFinished) { + this.inner = inner; + this.innerCallFinished = innerCallFinished; + } + + @Logged(sampleRate = 1.0) + @Override + public void process(Executor executor) throws InterruptedException { + executor.execute(() -> { + inner.doWork(); + innerCallFinished.countDown(); + }); + innerCallFinished.await(5, TimeUnit.SECONDS); + } + } + + @Test + @DisplayName("BEFORE: a plain, unwrapped executor loses the authenticated user for the nested call") + void withoutPropagation_innerCallLosesCallerIdentity() throws InterruptedException { + LoggedAspect aspect = newAspect(); + rawExecutor = Executors.newSingleThreadExecutor(); + CountDownLatch latch = new CountDownLatch(1); + InnerService inner = proxy(new InnerServiceImpl(), aspect); + OuterService outer = proxy(new OuterServiceImpl(inner, latch), aspect); + + authenticateAs("alice"); + System.out.println("--- WITHOUT SecurityContextPropagatingExecutor ---"); + outer.process(rawExecutor); + + MethodInvocationEvent innerEvent = events.stream() + .filter(e -> e.methodName().equals("doWork")) + .findFirst().orElseThrow(); + + System.out.println("Inner call caller identity = " + innerEvent.callerIdentity()); + assertThat(innerEvent.callerIdentity()).isEqualTo("unknown"); + } + + @Test + @DisplayName("AFTER: SecurityContextPropagatingExecutor keeps the authenticated user for the nested call") + void withPropagation_innerCallKeepsCallerIdentity() throws InterruptedException { + LoggedAspect aspect = newAspect(); + rawExecutor = Executors.newSingleThreadExecutor(); + Executor propagatingExecutor = new SecurityContextPropagatingExecutor(rawExecutor); + CountDownLatch latch = new CountDownLatch(1); + InnerService inner = proxy(new InnerServiceImpl(), aspect); + OuterService outer = proxy(new OuterServiceImpl(inner, latch), aspect); + + authenticateAs("alice"); + System.out.println("--- WITH SecurityContextPropagatingExecutor ---"); + outer.process(propagatingExecutor); + + MethodInvocationEvent innerEvent = events.stream() + .filter(e -> e.methodName().equals("doWork")) + .findFirst().orElseThrow(); + + System.out.println("Inner call caller identity = " + innerEvent.callerIdentity()); + assertThat(innerEvent.callerIdentity()).isEqualTo("user:alice"); + } +} diff --git a/logged-spring/src/test/java/com/fayupable/logged/spring/security/RequestAttributesPropagatingExecutorTest.java b/logged-spring/src/test/java/com/fayupable/logged/spring/security/RequestAttributesPropagatingExecutorTest.java new file mode 100644 index 0000000..c55c142 --- /dev/null +++ b/logged-spring/src/test/java/com/fayupable/logged/spring/security/RequestAttributesPropagatingExecutorTest.java @@ -0,0 +1,139 @@ +package com.fayupable.logged.spring.security; + +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Nested; +import org.junit.jupiter.api.Test; +import org.springframework.mock.web.MockHttpServletRequest; +import org.springframework.web.context.request.RequestAttributes; +import org.springframework.web.context.request.RequestContextHolder; +import org.springframework.web.context.request.ServletRequestAttributes; + +import java.util.concurrent.CountDownLatch; +import java.util.concurrent.ExecutorService; +import java.util.concurrent.Executors; +import java.util.concurrent.TimeUnit; +import java.util.concurrent.atomic.AtomicReference; + +import static org.assertj.core.api.Assertions.assertThat; +import static org.assertj.core.api.Assertions.assertThatThrownBy; + +@DisplayName("RequestAttributesPropagatingExecutor") +class RequestAttributesPropagatingExecutorTest { + + private ExecutorService delegate; + + @AfterEach + void tearDown() { + if (delegate != null) { + delegate.shutdownNow(); + } + RequestContextHolder.resetRequestAttributes(); + } + + private RequestAttributes attributesFrom(String remoteAddr) { + MockHttpServletRequest request = new MockHttpServletRequest(); + request.setRemoteAddr(remoteAddr); + return new ServletRequestAttributes(request); + } + + private void executeAndAwait(RequestAttributesPropagatingExecutor executor, Runnable command) throws InterruptedException { + CountDownLatch latch = new CountDownLatch(1); + executor.execute(() -> { + try { + command.run(); + } finally { + latch.countDown(); + } + }); + assertThat(latch.await(5, TimeUnit.SECONDS)).isTrue(); + } + + @Nested + @DisplayName("on a platform thread pool") + class OnPlatformThreadPool { + + @Test + @DisplayName("propagates the submitting thread's request attributes onto the pool thread") + void propagatesRequestAttributes() throws InterruptedException { + delegate = Executors.newFixedThreadPool(1); + RequestAttributesPropagatingExecutor executor = new RequestAttributesPropagatingExecutor(delegate); + AtomicReference observed = new AtomicReference<>(); + + RequestAttributes submitted = attributesFrom("203.0.113.5"); + RequestContextHolder.setRequestAttributes(submitted); + executeAndAwait(executor, () -> observed.set(RequestAttributesPropagation.capture())); + + assertThat(observed.get()).isSameAs(submitted); + } + + @Test + @DisplayName("propagates null when there is no active request on the submitting thread") + void propagatesNullWhenNothingActive() throws InterruptedException { + delegate = Executors.newFixedThreadPool(1); + RequestAttributesPropagatingExecutor executor = new RequestAttributesPropagatingExecutor(delegate); + AtomicReference observed = new AtomicReference<>(attributesFrom("0.0.0.0")); + + executeAndAwait(executor, () -> observed.set(RequestAttributesPropagation.capture())); + + assertThat(observed.get()).isNull(); + } + + @Test + @DisplayName("truly restores the executor thread's own request attributes, not merely masked by the next wrapped task's own adopt()") + void trulyRestoresRequestAttributesOnExecutorThread() throws InterruptedException { + delegate = Executors.newFixedThreadPool(1); + RequestAttributesPropagatingExecutor executor = new RequestAttributesPropagatingExecutor(delegate); + + RequestContextHolder.setRequestAttributes(attributesFrom("203.0.113.5")); + executeAndAwait(executor, () -> { }); + RequestContextHolder.resetRequestAttributes(); + + AtomicReference observedWithoutWrapper = new AtomicReference<>(attributesFrom("0.0.0.0")); + CountDownLatch latch = new CountDownLatch(1); + delegate.execute(() -> { + observedWithoutWrapper.set(RequestAttributesPropagation.capture()); + latch.countDown(); + }); + assertThat(latch.await(5, TimeUnit.SECONDS)).isTrue(); + + assertThat(observedWithoutWrapper.get()).isNull(); + } + + @Test + @DisplayName("still restores the executor thread's request attributes when the submitted task throws") + void restoresAttributesEvenWhenTaskThrows() throws InterruptedException { + delegate = Executors.newFixedThreadPool(1); + RequestAttributesPropagatingExecutor executor = new RequestAttributesPropagatingExecutor(delegate); + + RequestContextHolder.setRequestAttributes(attributesFrom("203.0.113.5")); + CountDownLatch latch = new CountDownLatch(1); + executor.execute(() -> { + try { + throw new IllegalStateException("boom"); + } finally { + latch.countDown(); + } + }); + assertThat(latch.await(5, TimeUnit.SECONDS)).isTrue(); + RequestContextHolder.resetRequestAttributes(); + + AtomicReference observedAfterFailure = new AtomicReference<>(attributesFrom("0.0.0.0")); + executeAndAwait(executor, () -> observedAfterFailure.set(RequestAttributesPropagation.capture())); + + assertThat(observedAfterFailure.get()).isNull(); + } + } + + @Nested + @DisplayName("constructor") + class Constructor { + + @Test + @DisplayName("rejects a null delegate") + void rejectsNullDelegate() { + assertThatThrownBy(() -> new RequestAttributesPropagatingExecutor(null)) + .isInstanceOf(NullPointerException.class); + } + } +} diff --git a/logged-spring/src/test/java/com/fayupable/logged/spring/security/RequestAttributesPropagationTest.java b/logged-spring/src/test/java/com/fayupable/logged/spring/security/RequestAttributesPropagationTest.java new file mode 100644 index 0000000..9edcdf1 --- /dev/null +++ b/logged-spring/src/test/java/com/fayupable/logged/spring/security/RequestAttributesPropagationTest.java @@ -0,0 +1,99 @@ +package com.fayupable.logged.spring.security; + +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Nested; +import org.junit.jupiter.api.Test; +import org.springframework.mock.web.MockHttpServletRequest; +import org.springframework.web.context.request.RequestAttributes; +import org.springframework.web.context.request.RequestContextHolder; +import org.springframework.web.context.request.ServletRequestAttributes; + +import static org.assertj.core.api.Assertions.assertThat; + +@DisplayName("RequestAttributesPropagation") +class RequestAttributesPropagationTest { + + @AfterEach + void tearDown() { + RequestContextHolder.resetRequestAttributes(); + } + + private RequestAttributes attributesFrom(String remoteAddr) { + MockHttpServletRequest request = new MockHttpServletRequest(); + request.setRemoteAddr(remoteAddr); + return new ServletRequestAttributes(request); + } + + @Nested + @DisplayName("capture()") + class Capture { + + @Test + @DisplayName("returns null when there is no active request on this thread") + void returnsNullWhenNothingActive() { + assertThat(RequestAttributesPropagation.capture()).isNull(); + } + + @Test + @DisplayName("returns the currently active request attributes") + void returnsActiveAttributes() { + RequestAttributes attributes = attributesFrom("203.0.113.5"); + RequestContextHolder.setRequestAttributes(attributes); + + assertThat(RequestAttributesPropagation.capture()).isSameAs(attributes); + } + } + + @Nested + @DisplayName("adopt()") + class Adopt { + + @Test + @DisplayName("makes the given request attributes active on this thread") + void makesAttributesActive() { + RequestAttributes attributes = attributesFrom("203.0.113.5"); + + Runnable restore = RequestAttributesPropagation.adopt(attributes); + try { + assertThat(RequestAttributesPropagation.capture()).isSameAs(attributes); + } finally { + restore.run(); + } + } + + @Test + @DisplayName("restores the previously active attributes once the returned Runnable is run") + void restoresPreviousAttributesOnRun() { + RequestAttributes original = attributesFrom("203.0.113.5"); + RequestContextHolder.setRequestAttributes(original); + + Runnable restore = RequestAttributesPropagation.adopt(attributesFrom("198.51.100.9")); + restore.run(); + + assertThat(RequestAttributesPropagation.capture()).isSameAs(original); + } + + @Test + @DisplayName("clears this thread's attributes once the returned Runnable is run, when nothing was active before") + void clearsAttributesOnRunWhenNothingWasActiveBefore() { + Runnable restore = RequestAttributesPropagation.adopt(attributesFrom("198.51.100.9")); + restore.run(); + + assertThat(RequestAttributesPropagation.capture()).isNull(); + } + + @Test + @DisplayName("clears any active attributes when adopting null") + void clearsAttributesWhenAdoptingNull() { + RequestContextHolder.setRequestAttributes(attributesFrom("203.0.113.5")); + + Runnable restore = RequestAttributesPropagation.adopt(null); + try { + assertThat(RequestAttributesPropagation.capture()).isNull(); + } finally { + restore.run(); + } + } + } +} diff --git a/logged-spring/src/test/java/com/fayupable/logged/spring/security/RequestAttributesTaskDecoratorTest.java b/logged-spring/src/test/java/com/fayupable/logged/spring/security/RequestAttributesTaskDecoratorTest.java new file mode 100644 index 0000000..7665747 --- /dev/null +++ b/logged-spring/src/test/java/com/fayupable/logged/spring/security/RequestAttributesTaskDecoratorTest.java @@ -0,0 +1,92 @@ +package com.fayupable.logged.spring.security; + +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Nested; +import org.junit.jupiter.api.Test; +import org.springframework.mock.web.MockHttpServletRequest; +import org.springframework.scheduling.concurrent.ThreadPoolTaskExecutor; +import org.springframework.web.context.request.RequestAttributes; +import org.springframework.web.context.request.RequestContextHolder; +import org.springframework.web.context.request.ServletRequestAttributes; + +import java.util.concurrent.CountDownLatch; +import java.util.concurrent.TimeUnit; +import java.util.concurrent.atomic.AtomicReference; + +import static org.assertj.core.api.Assertions.assertThat; + +@DisplayName("RequestAttributesTaskDecorator") +class RequestAttributesTaskDecoratorTest { + + private ThreadPoolTaskExecutor executor; + + @AfterEach + void tearDown() { + if (executor != null) { + executor.shutdown(); + } + RequestContextHolder.resetRequestAttributes(); + } + + private RequestAttributes attributesFrom(String remoteAddr) { + MockHttpServletRequest request = new MockHttpServletRequest(); + request.setRemoteAddr(remoteAddr); + return new ServletRequestAttributes(request); + } + + private ThreadPoolTaskExecutor newDecoratedExecutor() { + ThreadPoolTaskExecutor taskExecutor = new ThreadPoolTaskExecutor(); + taskExecutor.setCorePoolSize(1); + taskExecutor.setMaxPoolSize(1); + taskExecutor.setTaskDecorator(new RequestAttributesTaskDecorator()); + taskExecutor.initialize(); + return taskExecutor; + } + + private void submitAndAwait(ThreadPoolTaskExecutor taskExecutor, Runnable command) throws InterruptedException { + CountDownLatch latch = new CountDownLatch(1); + taskExecutor.execute(() -> { + try { + command.run(); + } finally { + latch.countDown(); + } + }); + assertThat(latch.await(5, TimeUnit.SECONDS)).isTrue(); + } + + @Nested + @DisplayName("as a Spring TaskExecutor's TaskDecorator") + class AsTaskExecutorDecorator { + + @Test + @DisplayName("propagates the submitting thread's request attributes onto the executor thread") + void propagatesRequestAttributes() throws InterruptedException { + executor = newDecoratedExecutor(); + AtomicReference observed = new AtomicReference<>(); + + RequestAttributes submitted = attributesFrom("203.0.113.5"); + RequestContextHolder.setRequestAttributes(submitted); + submitAndAwait(executor, () -> observed.set(RequestAttributesPropagation.capture())); + + assertThat(observed.get()).isSameAs(submitted); + } + + @Test + @DisplayName("truly restores the executor thread's own request attributes, not merely masked by the next wrapped task's own adopt()") + void trulyRestoresRequestAttributesOnExecutorThread() throws InterruptedException { + executor = newDecoratedExecutor(); + + RequestContextHolder.setRequestAttributes(attributesFrom("203.0.113.5")); + submitAndAwait(executor, () -> { }); + RequestContextHolder.resetRequestAttributes(); + + executor.setTaskDecorator(null); + AtomicReference observedWithoutDecoration = new AtomicReference<>(attributesFrom("0.0.0.0")); + submitAndAwait(executor, () -> observedWithoutDecoration.set(RequestAttributesPropagation.capture())); + + assertThat(observedWithoutDecoration.get()).isNull(); + } + } +} diff --git a/logged-spring/src/test/java/com/fayupable/logged/spring/security/SecurityContextPropagatingExecutorTest.java b/logged-spring/src/test/java/com/fayupable/logged/spring/security/SecurityContextPropagatingExecutorTest.java new file mode 100644 index 0000000..75560b2 --- /dev/null +++ b/logged-spring/src/test/java/com/fayupable/logged/spring/security/SecurityContextPropagatingExecutorTest.java @@ -0,0 +1,127 @@ +package com.fayupable.logged.spring.security; + +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Nested; +import org.junit.jupiter.api.Test; +import org.springframework.security.authentication.UsernamePasswordAuthenticationToken; +import org.springframework.security.core.context.SecurityContext; +import org.springframework.security.core.context.SecurityContextHolder; + +import java.util.concurrent.CountDownLatch; +import java.util.concurrent.ExecutorService; +import java.util.concurrent.Executors; +import java.util.concurrent.TimeUnit; +import java.util.concurrent.atomic.AtomicReference; + +import static org.assertj.core.api.Assertions.assertThat; +import static org.assertj.core.api.Assertions.assertThatThrownBy; + +@DisplayName("SecurityContextPropagatingExecutor") +class SecurityContextPropagatingExecutorTest { + + private ExecutorService delegate; + + @AfterEach + void tearDown() { + if (delegate != null) { + delegate.shutdownNow(); + } + SecurityContextHolder.clearContext(); + } + + private SecurityContext contextAuthenticatedAs(String username) { + SecurityContext context = SecurityContextHolder.createEmptyContext(); + context.setAuthentication(new UsernamePasswordAuthenticationToken(username, "password")); + return context; + } + + private void executeAndAwait(SecurityContextPropagatingExecutor executor, Runnable command) throws InterruptedException { + CountDownLatch latch = new CountDownLatch(1); + executor.execute(() -> { + try { + command.run(); + } finally { + latch.countDown(); + } + }); + assertThat(latch.await(5, TimeUnit.SECONDS)).isTrue(); + } + + @Nested + @DisplayName("on a platform thread pool") + class OnPlatformThreadPool { + + @Test + @DisplayName("propagates the submitting thread's authenticated user onto the pool thread") + void propagatesSecurityContext() throws InterruptedException { + delegate = Executors.newFixedThreadPool(1); + SecurityContextPropagatingExecutor executor = new SecurityContextPropagatingExecutor(delegate); + AtomicReference observedUsername = new AtomicReference<>(); + + SecurityContextHolder.setContext(contextAuthenticatedAs("alice")); + executeAndAwait(executor, () -> + observedUsername.set(SecurityContextPropagation.capture().getAuthentication().getName())); + + assertThat(observedUsername.get()).isEqualTo("alice"); + } + + @Test + @DisplayName("truly restores the executor thread's own security context, not merely masked by the next wrapped task's own adopt()") + void trulyRestoresSecurityContextOnExecutorThread() throws InterruptedException { + delegate = Executors.newFixedThreadPool(1); + SecurityContextPropagatingExecutor executor = new SecurityContextPropagatingExecutor(delegate); + + SecurityContextHolder.setContext(contextAuthenticatedAs("alice")); + executeAndAwait(executor, () -> { }); + SecurityContextHolder.clearContext(); + + AtomicReference observedAuthenticatedWithoutWrapper = new AtomicReference<>(true); + CountDownLatch latch = new CountDownLatch(1); + delegate.execute(() -> { + observedAuthenticatedWithoutWrapper.set(SecurityContextPropagation.capture().getAuthentication() != null); + latch.countDown(); + }); + assertThat(latch.await(5, TimeUnit.SECONDS)).isTrue(); + + assertThat(observedAuthenticatedWithoutWrapper.get()).isFalse(); + } + + @Test + @DisplayName("still restores the executor thread's security context when the submitted task throws") + void restoresContextEvenWhenTaskThrows() throws InterruptedException { + delegate = Executors.newFixedThreadPool(1); + SecurityContextPropagatingExecutor executor = new SecurityContextPropagatingExecutor(delegate); + + SecurityContextHolder.setContext(contextAuthenticatedAs("alice")); + CountDownLatch latch = new CountDownLatch(1); + executor.execute(() -> { + try { + throw new IllegalStateException("boom"); + } finally { + latch.countDown(); + } + }); + assertThat(latch.await(5, TimeUnit.SECONDS)).isTrue(); + SecurityContextHolder.clearContext(); + + AtomicReference observedAuthenticatedAfterFailure = new AtomicReference<>(true); + executeAndAwait(executor, () -> + observedAuthenticatedAfterFailure.set(SecurityContextPropagation.capture().getAuthentication() != null)); + + assertThat(observedAuthenticatedAfterFailure.get()).isFalse(); + } + } + + @Nested + @DisplayName("constructor") + class Constructor { + + @Test + @DisplayName("rejects a null delegate") + void rejectsNullDelegate() { + assertThatThrownBy(() -> new SecurityContextPropagatingExecutor(null)) + .isInstanceOf(NullPointerException.class); + } + } +} diff --git a/logged-spring/src/test/java/com/fayupable/logged/spring/security/SecurityContextPropagationTest.java b/logged-spring/src/test/java/com/fayupable/logged/spring/security/SecurityContextPropagationTest.java new file mode 100644 index 0000000..38edc83 --- /dev/null +++ b/logged-spring/src/test/java/com/fayupable/logged/spring/security/SecurityContextPropagationTest.java @@ -0,0 +1,89 @@ +package com.fayupable.logged.spring.security; + +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Nested; +import org.junit.jupiter.api.Test; +import org.springframework.security.authentication.UsernamePasswordAuthenticationToken; +import org.springframework.security.core.context.SecurityContext; +import org.springframework.security.core.context.SecurityContextHolder; + +import static org.assertj.core.api.Assertions.assertThat; + +@DisplayName("SecurityContextPropagation") +class SecurityContextPropagationTest { + + @AfterEach + void tearDown() { + SecurityContextHolder.clearContext(); + } + + private SecurityContext contextAuthenticatedAs(String username) { + SecurityContext context = SecurityContextHolder.createEmptyContext(); + context.setAuthentication(new UsernamePasswordAuthenticationToken(username, "password")); + return context; + } + + @Nested + @DisplayName("capture()") + class Capture { + + @Test + @DisplayName("never returns null, even when nothing was ever set on this thread") + void neverReturnsNull() { + assertThat(SecurityContextPropagation.capture()).isNotNull(); + } + + @Test + @DisplayName("returns the currently active security context") + void returnsActiveContext() { + SecurityContext context = contextAuthenticatedAs("alice"); + SecurityContextHolder.setContext(context); + + assertThat(SecurityContextPropagation.capture()).isSameAs(context); + } + } + + @Nested + @DisplayName("adopt()") + class Adopt { + + @Test + @DisplayName("makes the given security context active on this thread") + void makesContextActive() { + SecurityContext context = contextAuthenticatedAs("alice"); + + Runnable restore = SecurityContextPropagation.adopt(context); + try { + assertThat(SecurityContextPropagation.capture()).isSameAs(context); + } finally { + restore.run(); + } + } + + @Test + @DisplayName("restores the previously active context once the returned Runnable is run") + void restoresPreviousContextOnRun() { + SecurityContext original = contextAuthenticatedAs("alice"); + SecurityContextHolder.setContext(original); + + Runnable restore = SecurityContextPropagation.adopt(contextAuthenticatedAs("bob")); + restore.run(); + + assertThat(SecurityContextPropagation.capture()).isSameAs(original); + } + + @Test + @DisplayName("clears the context when adopting null") + void clearsContextWhenAdoptingNull() { + SecurityContextHolder.setContext(contextAuthenticatedAs("alice")); + + Runnable restore = SecurityContextPropagation.adopt(null); + try { + assertThat(SecurityContextPropagation.capture().getAuthentication()).isNull(); + } finally { + restore.run(); + } + } + } +} diff --git a/logged-spring/src/test/java/com/fayupable/logged/spring/security/SecurityContextTaskDecoratorTest.java b/logged-spring/src/test/java/com/fayupable/logged/spring/security/SecurityContextTaskDecoratorTest.java new file mode 100644 index 0000000..0c8cc2a --- /dev/null +++ b/logged-spring/src/test/java/com/fayupable/logged/spring/security/SecurityContextTaskDecoratorTest.java @@ -0,0 +1,92 @@ +package com.fayupable.logged.spring.security; + +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Nested; +import org.junit.jupiter.api.Test; +import org.springframework.scheduling.concurrent.ThreadPoolTaskExecutor; +import org.springframework.security.authentication.UsernamePasswordAuthenticationToken; +import org.springframework.security.core.context.SecurityContext; +import org.springframework.security.core.context.SecurityContextHolder; + +import java.util.concurrent.CountDownLatch; +import java.util.concurrent.TimeUnit; +import java.util.concurrent.atomic.AtomicReference; + +import static org.assertj.core.api.Assertions.assertThat; + +@DisplayName("SecurityContextTaskDecorator") +class SecurityContextTaskDecoratorTest { + + private ThreadPoolTaskExecutor executor; + + @AfterEach + void tearDown() { + if (executor != null) { + executor.shutdown(); + } + SecurityContextHolder.clearContext(); + } + + private SecurityContext contextAuthenticatedAs(String username) { + SecurityContext context = SecurityContextHolder.createEmptyContext(); + context.setAuthentication(new UsernamePasswordAuthenticationToken(username, "password")); + return context; + } + + private ThreadPoolTaskExecutor newDecoratedExecutor() { + ThreadPoolTaskExecutor taskExecutor = new ThreadPoolTaskExecutor(); + taskExecutor.setCorePoolSize(1); + taskExecutor.setMaxPoolSize(1); + taskExecutor.setTaskDecorator(new SecurityContextTaskDecorator()); + taskExecutor.initialize(); + return taskExecutor; + } + + private void submitAndAwait(ThreadPoolTaskExecutor taskExecutor, Runnable command) throws InterruptedException { + CountDownLatch latch = new CountDownLatch(1); + taskExecutor.execute(() -> { + try { + command.run(); + } finally { + latch.countDown(); + } + }); + assertThat(latch.await(5, TimeUnit.SECONDS)).isTrue(); + } + + @Nested + @DisplayName("as a Spring TaskExecutor's TaskDecorator") + class AsTaskExecutorDecorator { + + @Test + @DisplayName("propagates the submitting thread's authenticated user onto the executor thread") + void propagatesSecurityContext() throws InterruptedException { + executor = newDecoratedExecutor(); + AtomicReference observedUsername = new AtomicReference<>(); + + SecurityContextHolder.setContext(contextAuthenticatedAs("alice")); + submitAndAwait(executor, () -> + observedUsername.set(SecurityContextPropagation.capture().getAuthentication().getName())); + + assertThat(observedUsername.get()).isEqualTo("alice"); + } + + @Test + @DisplayName("truly restores the executor thread's own security context, not merely masked by the next wrapped task's own adopt()") + void trulyRestoresSecurityContextOnExecutorThread() throws InterruptedException { + executor = newDecoratedExecutor(); + + SecurityContextHolder.setContext(contextAuthenticatedAs("alice")); + submitAndAwait(executor, () -> { }); + SecurityContextHolder.clearContext(); + + executor.setTaskDecorator(null); + AtomicReference observedAuthenticatedWithoutDecoration = new AtomicReference<>(true); + submitAndAwait(executor, () -> + observedAuthenticatedWithoutDecoration.set(SecurityContextPropagation.capture().getAuthentication() != null)); + + assertThat(observedAuthenticatedWithoutDecoration.get()).isFalse(); + } + } +} diff --git a/pom.xml b/pom.xml index b128cba..ffc4a19 100644 --- a/pom.xml +++ b/pom.xml @@ -6,7 +6,7 @@ com.fayupable logged-lib - 1.0.0 + 1.1.0 pom logged-lib @@ -29,6 +29,7 @@ 5.11.4 3.27.7 5.15.2 + 13.6 3.6.0 0.8.12 @@ -79,6 +80,11 @@ ${mockito.version} test + + io.github.openfeign + feign-core + ${feign.version} +