diff --git a/docker-compose.yml b/docker-compose.yml index 8dd773d..9b61b97 100644 --- a/docker-compose.yml +++ b/docker-compose.yml @@ -154,5 +154,50 @@ services: ports: - "3000:3000" + loki: + # Log aggregation — single-binary, filesystem storage (Phase 18b). Grafana queries it as a + # second data source; promtail (below) feeds it. `full` profile because it stores the + # containerised app's logs, like the rest of the observability stack. + profiles: ["full"] + image: grafana/loki:3.1.1 + container_name: shopsphere-loki + command: ["-config.file=/etc/loki/loki-config.yml"] + volumes: + - ./observability/loki/loki-config.yml:/etc/loki/loki-config.yml:ro + ports: + - "3100:3100" + + promtail: + # Tails the app container's stdout JSON logs and ships them to Loki (Phase 18b). Reads the + # Docker socket to discover the `shopsphere-app` container; no app code or logging change needed. + profiles: ["full"] + image: grafana/promtail:3.1.1 + container_name: shopsphere-promtail + command: ["-config.file=/etc/promtail/promtail-config.yml"] + depends_on: + loki: + condition: service_started + volumes: + - ./observability/promtail/promtail-config.yml:/etc/promtail/promtail-config.yml:ro + # Promtail discovers containers and reads their JSON logs via the Docker engine API. + - /var/run/docker.sock:/var/run/docker.sock + + kafka-ui: + # Browse topics, partitions, and consumer-group offsets at http://localhost:8081 (Phase 18b). + # Needs only the broker, but stays under `full` so `docker compose up -d` keeps the dev loop + # minimal (Postgres + Kafka), consistent with how the app and metrics stack are gated. + profiles: ["full"] + image: kafbat/kafka-ui:v1.0.0 + container_name: shopsphere-kafka-ui + depends_on: + kafka: + condition: service_healthy + environment: + KAFKA_CLUSTERS_0_NAME: shopsphere + KAFKA_CLUSTERS_0_BOOTSTRAPSERVERS: kafka:29092 + DYNAMIC_CONFIG_ENABLED: "true" + ports: + - "8081:8080" + volumes: shopsphere-pgdata: diff --git a/docs/adr/0018b-loki-promtail-and-kafka-ui.md b/docs/adr/0018b-loki-promtail-and-kafka-ui.md new file mode 100644 index 0000000..d0f9343 --- /dev/null +++ b/docs/adr/0018b-loki-promtail-and-kafka-ui.md @@ -0,0 +1,42 @@ +--- +status: accepted +date: 2026-06-06 +cites: PragProg, APoSD, PoEAA, XP +--- + +# 0018b — Loki + promtail for logs, Kafbat Kafka UI for the broker + +Phase 18a made ShopSphere's **metrics** legible (Prometheus + a provisioned Grafana). Phase 18b does the same for its **logs** and its **broker**. The app already emits JSON logs (`LogstashEncoder`, since Phase 9) and already runs Kafka; what was missing was a place to *search* those logs by order and a window onto topics, partitions, and consumer offsets. This phase adds three containers — `loki`, `promtail`, `kafbat/kafka-ui` — and one small application change: every module now stamps `orderId` onto its log lines so a single Loki query follows an order across the whole system. + +## Loki + promtail over ELK + +The log backend is **Grafana Loki**, fed by **promtail**, not Elasticsearch + Logstash + Kibana. **XP YAGNI / PragProg "good enough":** Loki indexes only labels and stores the raw log line compressed — there is no full-text inverted index to provision, tune, or feed gigabytes of heap. For a single-node local stack whose logs are disposable (`docker compose down` wipes them), ELK is a database to operate where a `grep`-over-labels is all the acceptance check needs. Loki also *reuses the Grafana we already provisioned in 18a* — logs land as a second data source next to the metrics, so one pane explores both. ELK would have meant a second UI (Kibana) and a second mental model. + +Promtail discovers the app container through the Docker engine API (the mounted socket) and ships its stdout verbatim. **The app stays ignorant of its log shipping** — the same posture as 18a's pull-based metrics (**PoEAA / PragProg**): no logback appender pointed at Loki, no network dependency compiled into the app, no code change to redirect logs elsewhere later. Logging topology is config, not code. + +## Query by line filter, not by label — cardinality is the trap + +The headline acceptance check is: search Loki for an `orderId` and get back every module's line for that order. The naive way to enable it is to parse the JSON in promtail and promote `orderId` to a Loki **label**. That is the classic Loki footgun: labels are the index, and a UUID-valued label has unbounded cardinality — one stream per order — which is exactly what Loki's docs warn destroys it. So promtail ships the **raw JSON line** with only a low-cardinality `container` label, and the query is a **line filter**: + +``` +{container="shopsphere-app"} |= "" +``` + +Loki scans the (small, local) stream and matches the substring. **APoSD — the deep/cheap interface:** the expensive-to-misuse thing (labels) is kept tiny and stable; the flexible thing (arbitrary search) is pushed to query time where it costs nothing to be wrong. + +## One helper owns the correlation field — so every module says "orderId" the same way + +For the cross-module search to actually return Payment and Reservation lines (not just Ordering's), those modules have to put `orderId` on their log context. Before this phase only `OrderPlacement` did. Rather than copy-paste `MDC.put("orderId", …)/MDC.remove(…)` into four places — and risk one of them spelling the field differently or forgetting the `finally` — the field names live in **one deep module**, `common.OrderLog.withOrder(orderId[, customerId], body)` (**APoSD information hiding**). It stamps the MDC, runs the log statement, and always clears it. `OrderPlacement` was refactored onto it; `PaymentOrderingConsumer`, `PaymentEventsConsumer`, and `CatalogImpl` (reserve/confirm/release) now each emit one `orderId`-stamped line. `StructuredLogShapeTests` already pins the JSON field names the Loki query depends on; `OrderLogTests` pins that the helper stamps and always clears them. + +Scope is deliberately tight — the helper wraps only the `log.info(...)` call, never downstream work — so an order's MDC never leaks onto an unrelated thread or nests with another order's context. + +## Kafbat Kafka UI over Confluent Control Center + +The broker window is **kafbat/kafka-ui** (the community fork of provectus/kafka-ui), not Confluent Control Center. **XP / zero-external-dependency:** Control Center is part of Confluent Platform — heavier, license-encumbered for production, and oriented at a Confluent cluster. Kafbat is a single Apache-2.0 container that points at any broker via `BOOTSTRAPSERVERS` and shows topics, partition counts, and consumer-group offsets — which is the whole acceptance criterion. It needs only the broker, but stays under the `full` profile so `docker compose up -d` keeps the dev inner loop minimal (Postgres + Kafka), consistent with how 18a gated the metrics stack and Phase 10 gated the app. + +## Consequences + +Logs are now searchable by order across Ordering, Payment, and Reservation in the same Grafana that shows the metrics, and the broker is browsable at `http://localhost:8081` — all local containers, zero external dependency, `mvn verify` stays green (the new `OrderLogTests` plus the existing suite). Two honest limits, both recorded so they don't surprise later: + +- **The end-to-end Loki search is a manual QA step**, like 18a's "panels light up": it needs the `full` stack running and a QA walkthrough to generate an order, then `{container="shopsphere-app"} |= ""` in Grafana. No unit test asserts the rendered Loki result. +- **"Outbox" coverage is the Ordering leg, not a separate logger.** ShopSphere's outbox is Spring Modulith's event-publication table, drained to Kafka by Modulith's own machinery — there is no app code there to stamp. Ordering's `Order placed` line is emitted in the *same transaction* as the outbox insert, so it is the outbox's correlation point; the externalised event itself carries `orderId` and is visible in Kafka UI. We did not fabricate an outbox logger to satisfy the checklist literally. diff --git a/docs/modulith/components.puml b/docs/modulith/components.puml index f4e1f75..e317f5f 100644 --- a/docs/modulith/components.puml +++ b/docs/modulith/components.puml @@ -16,12 +16,12 @@ Container_Boundary("ShopSphere.ShopSphere_boundary", "ShopSphere", $tags="") { Component(ShopSphere.ShopSphere.Ordering, "Ordering", $techn="Module", $descr="", $tags="", $link="") } +Rel(ShopSphere.ShopSphere.Ordering, ShopSphere.ShopSphere.Identity, "depends on", $techn="", $tags="", $link="") Rel(ShopSphere.ShopSphere.Ordering, ShopSphere.ShopSphere.Common, "depends on", $techn="", $tags="", $link="") Rel(ShopSphere.ShopSphere.Ordering, ShopSphere.ShopSphere.Catalog, "uses", $techn="", $tags="", $link="") Rel(ShopSphere.ShopSphere.Ordering, ShopSphere.ShopSphere.Payment, "uses", $techn="", $tags="", $link="") -Rel(ShopSphere.ShopSphere.Payment, ShopSphere.ShopSphere.Common, "depends on", $techn="", $tags="", $link="") Rel(ShopSphere.ShopSphere.Catalog, ShopSphere.ShopSphere.Common, "depends on", $techn="", $tags="", $link="") -Rel(ShopSphere.ShopSphere.Ordering, ShopSphere.ShopSphere.Identity, "depends on", $techn="", $tags="", $link="") +Rel(ShopSphere.ShopSphere.Payment, ShopSphere.ShopSphere.Common, "depends on", $techn="", $tags="", $link="") SHOW_LEGEND(true) @enduml \ No newline at end of file diff --git a/docs/modulith/module-ordering.puml b/docs/modulith/module-ordering.puml index 50bc7d6..029e3d2 100644 --- a/docs/modulith/module-ordering.puml +++ b/docs/modulith/module-ordering.puml @@ -16,12 +16,12 @@ Container_Boundary("ShopSphere.ShopSphere_boundary", "ShopSphere", $tags="") { Component(ShopSphere.ShopSphere.Ordering, "Ordering", $techn="Module", $descr="", $tags="", $link="") } +Rel(ShopSphere.ShopSphere.Ordering, ShopSphere.ShopSphere.Identity, "depends on", $techn="", $tags="", $link="") Rel(ShopSphere.ShopSphere.Ordering, ShopSphere.ShopSphere.Common, "depends on", $techn="", $tags="", $link="") Rel(ShopSphere.ShopSphere.Ordering, ShopSphere.ShopSphere.Catalog, "uses", $techn="", $tags="", $link="") Rel(ShopSphere.ShopSphere.Ordering, ShopSphere.ShopSphere.Payment, "uses", $techn="", $tags="", $link="") -Rel(ShopSphere.ShopSphere.Payment, ShopSphere.ShopSphere.Common, "depends on", $techn="", $tags="", $link="") Rel(ShopSphere.ShopSphere.Catalog, ShopSphere.ShopSphere.Common, "depends on", $techn="", $tags="", $link="") -Rel(ShopSphere.ShopSphere.Ordering, ShopSphere.ShopSphere.Identity, "depends on", $techn="", $tags="", $link="") +Rel(ShopSphere.ShopSphere.Payment, ShopSphere.ShopSphere.Common, "depends on", $techn="", $tags="", $link="") SHOW_LEGEND(true) @enduml \ No newline at end of file diff --git a/observability/grafana/provisioning/datasources/loki.yml b/observability/grafana/provisioning/datasources/loki.yml new file mode 100644 index 0000000..22e3cca --- /dev/null +++ b/observability/grafana/provisioning/datasources/loki.yml @@ -0,0 +1,12 @@ +# Auto-provisions Loki as a second Grafana datasource on startup (Phase 18b). Prometheus (Phase 18a) +# stays the default; this adds logs alongside metrics so one Grafana explores both. +apiVersion: 1 + +datasources: + - name: Loki + uid: loki + type: loki + access: proxy + url: http://loki:3100 + isDefault: false + editable: false diff --git a/observability/loki/loki-config.yml b/observability/loki/loki-config.yml new file mode 100644 index 0000000..496dee9 --- /dev/null +++ b/observability/loki/loki-config.yml @@ -0,0 +1,41 @@ +# Single-binary Loki for local development (Phase 18b). +# +# Everything runs in one process with on-disk (filesystem) storage — no object store, no clustering. +# That is the right altitude for a dev/QA log backend: zero external dependency, matching the rest of +# the ShopSphere local stack. Retention and replication are intentionally left at defaults; logs are +# disposable here and the container's filesystem is wiped on `docker compose down`. +auth_enabled: false + +server: + http_listen_port: 3100 + grpc_listen_port: 9095 + log_level: warn + +common: + instance_addr: 127.0.0.1 + path_prefix: /loki + storage: + filesystem: + chunks_directory: /loki/chunks + rules_directory: /loki/rules + replication_factor: 1 + ring: + kvstore: + store: inmemory + +schema_config: + configs: + - from: 2024-01-01 + store: tsdb + object_store: filesystem + schema: v13 + index: + prefix: index_ + period: 24h + +limits_config: + # Promtail ships lines as fast as it tails; allow a little burst headroom for a QA walkthrough. + ingestion_rate_mb: 8 + ingestion_burst_size_mb: 16 + # Let queries reach back over a full local session. + reject_old_samples: false diff --git a/observability/promtail/promtail-config.yml b/observability/promtail/promtail-config.yml new file mode 100644 index 0000000..47403fe --- /dev/null +++ b/observability/promtail/promtail-config.yml @@ -0,0 +1,34 @@ +# Promtail — tails Docker container logs and pushes them to Loki (Phase 18b). +# +# It discovers running containers through the Docker engine API (the mounted /var/run/docker.sock), +# keeps only the ShopSphere app container, and ships each stdout line to Loki verbatim. The app +# already logs JSON (LogstashEncoder, logback-spring.xml) with orderId/customerId as top-level +# fields, so we do NOT parse fields into Loki labels — that would explode label cardinality. Instead +# the raw JSON line is stored and queried with a line filter, e.g. +# {container="shopsphere-app"} |= "" +# which returns every module's line for that order (Ordering, Payment, Reservation). +server: + http_listen_port: 9080 + grpc_listen_port: 0 + +positions: + filename: /tmp/positions.yaml + +clients: + - url: http://loki:3100/loki/api/v1/push + +scrape_configs: + - job_name: docker + docker_sd_configs: + - host: unix:///var/run/docker.sock + refresh_interval: 5s + relabel_configs: + # Keep only the app container; drop the broker, db, grafana, etc. + - source_labels: ['__meta_docker_container_name'] + regex: '/shopsphere-app' + action: keep + # Expose a clean `container` label (strip Docker's leading slash) for the query above. + - source_labels: ['__meta_docker_container_name'] + regex: '/(.*)' + target_label: container + replacement: '$1' diff --git a/src/main/java/com/shopsphere/catalog/CatalogImpl.java b/src/main/java/com/shopsphere/catalog/CatalogImpl.java index a4d53ad..9c2023a 100644 --- a/src/main/java/com/shopsphere/catalog/CatalogImpl.java +++ b/src/main/java/com/shopsphere/catalog/CatalogImpl.java @@ -1,6 +1,9 @@ package com.shopsphere.catalog; +import com.shopsphere.common.OrderLog; import io.micrometer.core.instrument.MeterRegistry; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; import org.springframework.stereotype.Service; import org.springframework.transaction.annotation.Transactional; @@ -14,6 +17,8 @@ @Service class CatalogImpl implements Catalog { + private static final Logger log = LoggerFactory.getLogger(CatalogImpl.class); + static final String PRODUCT_NOT_FOUND = "PRODUCT_NOT_FOUND"; static final String INSUFFICIENT_STOCK = "INSUFFICIENT_STOCK"; @@ -67,6 +72,12 @@ public ReservationOutcome reserve(UUID orderId, List items) { countReservations("held", decisions.size()); } + // Reservation's leg of the order's journey — stamped with orderId so a Loki orderId query + // returns the stock decision alongside Ordering's and Payment's lines. + boolean granted = allGranted; + OrderLog.withOrder(orderId, () -> + log.info("Reservation {} for {} item(s)", granted ? "granted" : "denied", decisions.size())); + List lines = decisions.stream() .map(Decision::toLine) .toList(); @@ -81,6 +92,7 @@ public void confirm(UUID orderId) { r.confirm(); } countReservations("confirmed", held.size()); + OrderLog.withOrder(orderId, () -> log.info("Reservation confirmed for {} item(s)", held.size())); } @Override @@ -94,6 +106,7 @@ public void release(UUID orderId) { r.release(); } countReservations("released", held.size()); + OrderLog.withOrder(orderId, () -> log.info("Reservation released for {} item(s)", held.size())); } @Override diff --git a/src/main/java/com/shopsphere/common/OrderLog.java b/src/main/java/com/shopsphere/common/OrderLog.java new file mode 100644 index 0000000..ab1728e --- /dev/null +++ b/src/main/java/com/shopsphere/common/OrderLog.java @@ -0,0 +1,49 @@ +package com.shopsphere.common; + +import org.slf4j.MDC; + +import java.util.UUID; + +/** + * The one place that knows how an order is correlated across log lines: it stamps {@code orderId} + * (and {@code customerId}, when known) into the SLF4J {@link MDC} for the duration of a log + * statement, then always clears them again. + * + *

Every module that touches an order — Ordering, Payment, Catalog/Reservation — logs through this + * helper so the {@code LogstashEncoder} lifts those fields to top-level JSON. A Loki query of the + * form {@code {container="shopsphere-app"} |= ""} then returns the whole journey of one + * order across every module, which is the headline acceptance check for the logging stack. + * + *

Scope is deliberately tight: wrap only the {@code log.info(...)} call, not downstream work, so + * the MDC never leaks onto an unrelated thread or nests with another order's context. + */ +public final class OrderLog { + + private static final String ORDER_ID = "orderId"; + private static final String CUSTOMER_ID = "customerId"; + + private OrderLog() { + } + + /** Run {@code body} with {@code orderId} stamped onto the MDC; clears it afterwards. */ + public static void withOrder(UUID orderId, Runnable body) { + withOrder(orderId, null, body); + } + + /** + * Run {@code body} with {@code orderId} (and {@code customerId}, if non-null) stamped onto the + * MDC; clears both afterwards, even if {@code body} throws. + */ + public static void withOrder(UUID orderId, UUID customerId, Runnable body) { + MDC.put(ORDER_ID, orderId.toString()); + if (customerId != null) { + MDC.put(CUSTOMER_ID, customerId.toString()); + } + try { + body.run(); + } finally { + MDC.remove(ORDER_ID); + MDC.remove(CUSTOMER_ID); + } + } +} diff --git a/src/main/java/com/shopsphere/ordering/OrderPlacement.java b/src/main/java/com/shopsphere/ordering/OrderPlacement.java index 42c2310..cfd32e8 100644 --- a/src/main/java/com/shopsphere/ordering/OrderPlacement.java +++ b/src/main/java/com/shopsphere/ordering/OrderPlacement.java @@ -3,10 +3,10 @@ import com.shopsphere.catalog.Catalog; import com.shopsphere.catalog.ProductPriceLookup; import com.shopsphere.common.Money; +import com.shopsphere.common.OrderLog; import com.shopsphere.payment.PaymentMethods; import org.slf4j.Logger; import org.slf4j.LoggerFactory; -import org.slf4j.MDC; import org.springframework.context.ApplicationEventPublisher; import org.springframework.stereotype.Component; import org.springframework.transaction.annotation.Transactional; @@ -120,16 +120,13 @@ CheckoutService.PlacedOrder place(UUID customerId, List.copyOf(eventLines)); events.publishEvent(placed); - // Structured, contextual log line — orderId/customerId land as top-level JSON fields via MDC. - MDC.put("orderId", order.getId().toString()); - MDC.put("customerId", customerId.toString()); - try { - log.info("Order placed with {} line(s), total {} {}", - eventLines.size(), runningTotal.amount(), runningTotal.currency()); - } finally { - MDC.remove("orderId"); - MDC.remove("customerId"); - } + // Structured, contextual log line — orderId/customerId land as top-level JSON fields via MDC, + // so a Loki orderId query picks this up as Ordering's leg of the order's journey (emitted in + // the same transaction as the outbox insert above). + Money total = runningTotal; + OrderLog.withOrder(order.getId(), customerId, () -> + log.info("Order placed with {} line(s), total {} {}", + eventLines.size(), total.amount(), total.currency())); return new CheckoutService.PlacedOrder(order.getId(), order.getStatus()); } diff --git a/src/main/java/com/shopsphere/ordering/PaymentEventsConsumer.java b/src/main/java/com/shopsphere/ordering/PaymentEventsConsumer.java index 3ea9ce0..5efe522 100644 --- a/src/main/java/com/shopsphere/ordering/PaymentEventsConsumer.java +++ b/src/main/java/com/shopsphere/ordering/PaymentEventsConsumer.java @@ -2,6 +2,7 @@ import com.fasterxml.jackson.databind.JsonNode; import com.fasterxml.jackson.databind.ObjectMapper; +import com.shopsphere.common.OrderLog; import com.shopsphere.common.ProcessedEvents; import org.apache.kafka.clients.consumer.ConsumerRecord; import org.slf4j.Logger; @@ -62,11 +63,13 @@ public void onPaymentEvent(ConsumerRecord record) throws Excepti case "PaymentSucceeded" -> { order.transitionTo(OrderStatus.PAID, now); events.publishEvent(new OrderPaid(UUID.randomUUID(), now, orderId, customerId)); + OrderLog.withOrder(orderId, customerId, () -> log.info("Order marked PAID")); } case "PaymentFailed" -> { String reason = textOrNull(tree, "reason"); order.transitionTo(OrderStatus.CANCELLED, now); events.publishEvent(new OrderCancelled(UUID.randomUUID(), now, orderId, customerId, reason)); + OrderLog.withOrder(orderId, customerId, () -> log.info("Order CANCELLED: {}", reason)); } default -> log.warn("Unknown payment event type: {}", eventType); } diff --git a/src/main/java/com/shopsphere/payment/PaymentOrderingConsumer.java b/src/main/java/com/shopsphere/payment/PaymentOrderingConsumer.java index f6c2054..48c1265 100644 --- a/src/main/java/com/shopsphere/payment/PaymentOrderingConsumer.java +++ b/src/main/java/com/shopsphere/payment/PaymentOrderingConsumer.java @@ -3,6 +3,7 @@ import com.fasterxml.jackson.databind.JsonNode; import com.fasterxml.jackson.databind.ObjectMapper; import com.shopsphere.common.Money; +import com.shopsphere.common.OrderLog; import com.shopsphere.common.ProcessedEvents; import io.micrometer.core.instrument.MeterRegistry; import org.slf4j.Logger; @@ -79,6 +80,11 @@ void process(OrderPlacedView placed) { }; // Counted only here, downstream of the markProcessed dedupe gate — redelivery never re-counts. meters.counter("payments_total", "outcome", metricOutcome).increment(); + + // Payment's leg of the order's journey — orderId/customerId stamped so a Loki orderId query + // returns this line alongside Ordering's and Reservation's. + OrderLog.withOrder(placed.orderId, placed.customerId, () -> + log.info("Charge {} for order", metricOutcome)); } private static String textOrNull(JsonNode tree, String field) { diff --git a/src/test/java/com/shopsphere/common/OrderLogTests.java b/src/test/java/com/shopsphere/common/OrderLogTests.java new file mode 100644 index 0000000..c453589 --- /dev/null +++ b/src/test/java/com/shopsphere/common/OrderLogTests.java @@ -0,0 +1,73 @@ +package com.shopsphere.common; + +import ch.qos.logback.classic.Logger; +import ch.qos.logback.classic.LoggerContext; +import ch.qos.logback.classic.spi.ILoggingEvent; +import ch.qos.logback.core.read.ListAppender; +import org.junit.jupiter.api.Test; +import org.slf4j.LoggerFactory; +import org.slf4j.MDC; + +import java.util.UUID; + +import static org.assertj.core.api.Assertions.assertThat; + +/** + * {@link OrderLog} is the one place that knows the MDC field names ({@code orderId}/{@code customerId}) + * the structured logs and the Loki dashboards key on. These tests pin that contract and the + * always-clean-up guarantee, so every module can stamp an order onto a log line the same way without + * re-deriving the field names. Mirrors the field names asserted in + * {@code com.shopsphere.ordering.StructuredLogShapeTests}. + */ +class OrderLogTests { + + private static final UUID ORDER = UUID.fromString("11111111-1111-1111-1111-111111111111"); + private static final UUID CUSTOMER = UUID.fromString("22222222-2222-2222-2222-222222222222"); + + @Test + void stampsOrderAndCustomerOntoTheLogLinesMdc() { + ListAppender appender = attachAppender(); + Logger log = (Logger) LoggerFactory.getLogger(OrderLogTests.class); + + OrderLog.withOrder(ORDER, CUSTOMER, () -> log.info("did a thing")); + + ILoggingEvent event = appender.list.get(0); + assertThat(event.getMDCPropertyMap()).containsEntry("orderId", ORDER.toString()); + assertThat(event.getMDCPropertyMap()).containsEntry("customerId", CUSTOMER.toString()); + } + + @Test + void stampsOrderOnlyWhenNoCustomerIsKnown() { + ListAppender appender = attachAppender(); + Logger log = (Logger) LoggerFactory.getLogger(OrderLogTests.class); + + OrderLog.withOrder(ORDER, () -> log.info("downstream consumer")); + + ILoggingEvent event = appender.list.get(0); + assertThat(event.getMDCPropertyMap()).containsEntry("orderId", ORDER.toString()); + assertThat(event.getMDCPropertyMap()).doesNotContainKey("customerId"); + } + + @Test + void clearsMdcAfterTheBodyEvenWhenItThrows() { + try { + OrderLog.withOrder(ORDER, CUSTOMER, () -> { + throw new IllegalStateException("boom"); + }); + } catch (IllegalStateException expected) { + // swallow — we only care that the MDC is clean afterwards + } + + assertThat(MDC.get("orderId")).isNull(); + assertThat(MDC.get("customerId")).isNull(); + } + + private ListAppender attachAppender() { + LoggerContext context = (LoggerContext) LoggerFactory.getILoggerFactory(); + ListAppender appender = new ListAppender<>(); + appender.setContext(context); + appender.start(); + ((Logger) LoggerFactory.getLogger(OrderLogTests.class)).addAppender(appender); + return appender; + } +}