diff --git a/.github/workflows/run-with-maven.yml b/.github/workflows/run-with-maven.yml index d3acbad..df8ed57 100644 --- a/.github/workflows/run-with-maven.yml +++ b/.github/workflows/run-with-maven.yml @@ -39,10 +39,10 @@ jobs: restore-keys: | ${{ runner.os }}-maven- - - name: Set up JDK 8 + - name: Set up JDK 17 uses: actions/setup-java@v2 with: - java-version: '8' + java-version: '17' distribution: 'adopt' cache: maven diff --git a/README.md b/README.md index 35c59a1..447934a 100644 --- a/README.md +++ b/README.md @@ -1,4 +1,4 @@ -# Structured Logging +# Structured Logging [](https://dmtech.de/) [![Apache License 2](https://img.shields.io/badge/license-MIT-blue.svg)](LICENSE) @@ -30,12 +30,37 @@ Now you can all without writing more code, because you already have all information you need in the context of your log messages. +## How? + +If there are log messages that happen in the context of an order, you may want to attach information about that order to +these log messages. + +```java + mdc(incomingOrder, () -> { + log.info("A new order has come in."); + + if(isValid(incomingOrder)){ + prepareForDelivery(incomingOrder); + } + }); +``` + +The `incomingOrder` will be attached to the log messages generated in this `try` block, including + +* the message from `log.info("A new order has come in.")` . +* all messages logged by `prepareForDelivery(...)`, `isValid(...)` +* all messages logged by methods called indirectly by the methods above + +Here's what a log message with an `incomingOrder` looks like in Kibana: + +![Kibana-Example](docs/structured-logging-kibana.png) + --- **Table of Contents** * [Why?](#why) -* [Example](#example) +* [How?](#how) * [Advantages](#advantages) * [Advantages over plain logging](#advantages-over-plain-logging) * [Advantages over using MDC directly](#advantages-over-using-mdc-directly) @@ -48,9 +73,11 @@ all without writing more code, because you already have all information you need * [Step 5: (also Optional) Test your logging](#step-5-also-optional-test-your-logging) * [Advanced usage](#advanced-usage) * [Define how Objects should be named in MDC](#define-how-objects-should-be-named-in-mdc) + * [Use try-with-resources instead of a callback](#use-try-with-resources-instead-of-a-callback) * [Changing serialization by using Jackson annotations](#changing-serialization-by-using-jackson-annotations) * [Changing serialization by using a custom ObjectMapper](#changing-serialization-by-using-a-custom-objectmapper) * [Changes](#changes) + * [3.0.0](#300) * [2.0.6](#206) * [2.0.5](#205) * [2.0.4](#204) @@ -63,31 +90,6 @@ all without writing more code, because you already have all information you need --- -## Example - -If there are log messages that happen in the context of an order, you may want to attach information about that order to -these log messages. - -```java - try(var c = MdcContext.of(incomingOrder)){ - log.info("A new order has come in."); - - if(isValid(incomingOrder)){ - prepareForDelivery(incomingOrder); - } - } -``` - -The `incomingOrder` will be attached to the log messages generated in this `try` block, including - -* the message from `log.info("A new order has come in.")` . -* all messages logged by `prepareForDelivery(...)`, `isValid(...)` -* all messages logged by methods called indirectly by the methods above - -Here's what a log message with an `incomingOrder` looks like in Kibana: - -![Kibana-Example](docs/structured-logging-kibana.png) - ## Advantages This approach has various advantages over both plain logging as well as @@ -143,7 +145,7 @@ If you use maven, add this to your pom.xml: de.dm.infrastructure structured-logging - 2.0.5 + 3.0.0 ``` @@ -178,26 +180,37 @@ The following configuration can be used as an example: ### Step 3: Put Objects into the logging context -Create a new `MdcContext` in a try-with-resources statement to define the scope in which context information should -be set: +use MdcContext.mdc(...) to define the scope in which context information should be set: ```java +import static de.dm.prom.structuredlogging.MdcContext.mdc; + +... + log.info("a message without context"); TimeMachine timeMachine=TimeMachineBuilder.build(); -//set the MdcContext as soon as possible after object (timeMachine) creation -try(var c = MdcContext.of(timeMachine)){ +mdc(timeMachine, () -> { log.info("time machine found. Trying to use it"); - travelSomewhereWith(timeMachine); - timeMachine.setFluxFactor(42); MdcContext.update(timeMachine); - travelSomewhereWith(timeMachine); -} + travelSomewhenWith(timeMachine); +}); + +log.info("another message without context"); +``` + +You can also return values: + +```java +var currentTime = mdc(timeMachine, () -> { + timeMachine.setFluxFactor(42); + return travelSomewhenWith(timeMachine); +}); log.info("another message without context"); ``` @@ -264,11 +277,11 @@ There are three ways to define the MDC key for the objects you put into the cont **2. Define it manually** ```java -try(var c = MdcContext.of("de_lorean", timeMachine)){ +mdc("de_lorean", timeMachine, () -> { ... MdcContext.update("de_lorean", timeMachine); ... -} +}); ``` **3. Provide an MdcKeySupplier** @@ -292,11 +305,30 @@ Then use it: ```java //MdcContext.of(...) is defined so that you can only use TimeMachineKey with a TimeMachine. -try(var c = MdcContext.of(TimeMachineKey.class, timeMachine)){ +mdc(TimeMachineKey.class, timeMachine, () -> { ... MdcContext.update(TimeMachineKey.class, timeMachine); ... -} +}); +``` + +### Use try-with-resources instead of a callback + +You can also use try-with-resources to manage your MDC context if you prefer that or need to. For example, the following code + +1. would not be possible with the callback API because `availableSeats` is not effectively final +1. would be inconvenient, because there are multiple values in the MDC context, which would require nested callbacks +1. may not be possible with the callback API if `seat.isAvaliable()` can throw **multiple** checked Exceptions. The callback API works with one checked Exception, though. + +```java +int availableSeats = 0; +seats.forEach(seat -> { + try (var s = MdcContext.of(seat); var c = MdcContext.of(cinema)) { + if (seat.isAvailable()) { // isAvailable() also logs + availableSeats++; + } + } +}); ``` ### Changing serialization by using Jackson annotations @@ -319,6 +351,12 @@ If you want to use your own ObjectMapper for serialization, you can exchange the ## Changes +### 3.0.0 + +* **Breaking Change**: Structured Logging now requires Java 17 +* **New Feature**: Convenience methods as an alternative to try-with-resources +* updated dependencies + ### 2.0.6 * **New Feature**: Made the used ObjectMapper configurable diff --git a/docs/structured-logging-kibana.png b/docs/structured-logging-kibana.png index 90a3233..3e02ce7 100644 Binary files a/docs/structured-logging-kibana.png and b/docs/structured-logging-kibana.png differ diff --git a/pom.xml b/pom.xml index a22fd21..e3a7e1b 100644 --- a/pom.xml +++ b/pom.xml @@ -1,11 +1,11 @@ - 4.0.0 de.dm.infrastructure structured-logging - ${project.version} + 3.0.0-SNAPSHOT structured-logging Structured logging and log testing @@ -29,63 +29,44 @@ - 2.0.2-SNAPSHOT - - 1.8 + 17 UTF-8 - 7.2 - 1.18.24 - 1.7.30 - 1.2.3 - 5.3.26 - 2.7.4 - 5.7.0 - 3.17.2 - 3.5.13 - 3.5.0 - 3.10.1 - 3.3.2 - 3.2.1 - 3.1.1 - 2.22.2 - 2.5.3 - 3.0.1 - 1.6.8 - 8.45.1 + UTF-8 + UTF-8 net.logstash.logback logstash-logback-encoder - ${logstash-logback-encoder.version} + 7.4 org.projectlombok lombok - ${lombok.version} + 1.18.30 provided org.slf4j slf4j-api - ${slf4j.version} + 2.0.9 ch.qos.logback logback-classic - ${logback.version} + 1.4.14 org.springframework spring-core - ${spring.version} + 6.1.1 true org.springframework.boot spring-boot - ${spring.boot.version} + 3.2.0 true compile @@ -94,37 +75,37 @@ org.springframework.boot spring-boot-starter-test - ${spring.boot.version} + 3.2.0 test org.junit.jupiter junit-jupiter-engine - ${junit-jupiter.version} + 5.10.1 test org.junit.jupiter junit-jupiter-api - ${junit-jupiter.version} + 5.10.1 test org.assertj assertj-core - ${assertj.version} + 3.24.2 test org.mockito mockito-core - ${mockito.version} + 5.8.0 test de.dm.infrastructure log-capture - ${log-capture.version} + 4.0.0 test @@ -135,7 +116,7 @@ org.apache.maven.plugins maven-compiler-plugin - ${maven-compiler-plugin.version} + 3.11.0 ${java.version} ${java.version} @@ -144,43 +125,12 @@ true - - org.apache.maven.plugins - maven-javadoc-plugin - ${maven-javadoc-plugin.version} - - ${java.version} - ${encoding} - - - - attach-javadoc - - jar - - - - - - org.apache.maven.plugins - maven-source-plugin - ${maven-source-plugin.version} - - - attach-sources - - jar - - - - org.apache.maven.plugins maven-checkstyle-plugin - ${maven-checkstyle-plugin.version} + 3.3.1 checkstyle.xml - UTF-8 true true false @@ -189,7 +139,7 @@ com.puppycrawl.tools checkstyle - ${checkstyle.version} + 10.12.5 @@ -205,12 +155,12 @@ org.apache.maven.plugins maven-surefire-plugin - ${maven-surefire-plugin.version} + 3.2.2 org.apache.maven.plugins maven-release-plugin - ${maven-release-plugin.version} + 3.0.1 @{project.version} @@ -218,7 +168,7 @@ org.sonatype.plugins nexus-staging-maven-plugin - ${nexus-staging-maven-plugin.version} + 1.6.13 true ossrh @@ -240,12 +190,12 @@ org.apache.maven.plugins maven-source-plugin - ${maven-source-plugin.version} + 3.3.0 org.apache.maven.plugins maven-javadoc-plugin - ${maven-javadoc-plugin.version} + 3.6.3 ${java.version} ${encoding} @@ -270,7 +220,7 @@ org.apache.maven.plugins maven-gpg-plugin - ${maven-gpg-plugin.version} + 3.1.0 sign-artifacts diff --git a/src/main/java/de/dm/prom/structuredlogging/MdcContext.java b/src/main/java/de/dm/prom/structuredlogging/MdcContext.java index 0a1f29c..8728d22 100644 --- a/src/main/java/de/dm/prom/structuredlogging/MdcContext.java +++ b/src/main/java/de/dm/prom/structuredlogging/MdcContext.java @@ -126,6 +126,113 @@ public static MdcContext of(Object mdcValue) { return new MdcContext(mdcValue.getClass().getSimpleName(), mdcValue); } + /** + * execute a supplier with MDC Context + * + * @param mdcValue the object to write to MDC + * @param supplier the callback to execute with the MDC Context + * @param type of return value + * @param type of checked Exception thrown (if any, can usually be inferred) + * + * @return the return value of the callback + * + * @throws E checked exception thrown by callback + */ + public static T mdc(Object mdcValue, MdcSupplier supplier) throws E { + try (MdcContext c = MdcContext.of(mdcValue)) { + return supplier.get(); + } + } + + /** + * execute a runnable with MDC Context + * + * @param mdcValue the object to write to MDC + * @param runnable the callback to execute with the MDC Context + * @param type of checked Exception thrown (if any, can usually be inferred) + * + * @throws E checked exception thrown by callback + */ + public static void mdc(Object mdcValue, MdcRunnable runnable) throws E { + try (MdcContext c = MdcContext.of(mdcValue)) { + runnable.run(); + } + } + + /** + * execute a supplier with MDC Context + * + * @param mdcKey MDC key to use + * @param mdcValue the object to write to MDC + * @param supplier the callback to execute with the MDC Context + * @param type of return value + * @param type of checked Exception thrown (if any, can usually be inferred) + * + * @return the return value of the callback + * + * @throws E checked exception thrown by callback + */ + public static T mdc(String mdcKey, Object mdcValue, MdcSupplier supplier) throws E { + try (MdcContext c = MdcContext.of(mdcKey, mdcValue)) { + return supplier.get(); + } + } + + /** + * execute a runnable with MDC Context + * + * @param mdcKey MDC key to use + * @param mdcValue the object to write to MDC + * @param runnable the callback to execute with the MDC Context + * @param type of checked Exception thrown (if any, can usually be inferred) + * + * @throws E checked exception thrown by callback + */ + public static void mdc(String mdcKey, Object mdcValue, MdcRunnable runnable) throws E { + try (MdcContext c = MdcContext.of(mdcKey, mdcValue)) { + runnable.run(); + } + } + + /** + * execute a supplier with MDC Context + * + * @param keySupplier {@link de.dm.prom.structuredlogging.MdcKeySupplier} implementation to describe which MDC key to use + * @param mdcValue the object to write to MDC + * @param supplier the callback to execute with the MDC Context + * @param type of return value + * @param type of checked Exception thrown (if any, can usually be inferred) + * @param the type of the object to serialize + * @param an implementation of MdcKeySupplier that supplies the MDC key for a certain type + * + * @return the return value of the callback + * + * @throws E checked exception thrown by callback + */ + public static > T mdc(Class keySupplier, M mdcValue, MdcSupplier supplier) throws E { + try (MdcContext c = MdcContext.of(keySupplier, mdcValue)) { + return supplier.get(); + } + } + + /** + * execute a runnable with MDC Context + * + * @param keySupplier {@link de.dm.prom.structuredlogging.MdcKeySupplier} implementation to describe which MDC key to use + * @param mdcValue the object to write to MDC + * @param runnable the callback to execute with the MDC Context + * @param type of checked Exception thrown (if any, can usually be inferred) + * @param the type of the object to serialize + * @param an implementation of MdcKeySupplier that supplies the MDC key for a certain type + * + * @throws E checked exception thrown by callback + */ + public static > void mdc(Class keySupplier, M mdcValue, MdcRunnable runnable) throws E { + try (MdcContext c = MdcContext.of(keySupplier, mdcValue)) { + runnable.run(); + } + } + /** * update an existing MDC context *

diff --git a/src/main/java/de/dm/prom/structuredlogging/MdcRunnable.java b/src/main/java/de/dm/prom/structuredlogging/MdcRunnable.java new file mode 100644 index 0000000..a9b8497 --- /dev/null +++ b/src/main/java/de/dm/prom/structuredlogging/MdcRunnable.java @@ -0,0 +1,15 @@ +package de.dm.prom.structuredlogging; + +/** + * Runnable that throws, to be able to handle MDC Context that throw one checked Exception + * + * @param thrown checked Exception + */ +public interface MdcRunnable { + /** + * callback to run with context + * + * @throws E thrown checked Exception + */ + void run() throws E; +} diff --git a/src/main/java/de/dm/prom/structuredlogging/MdcSupplier.java b/src/main/java/de/dm/prom/structuredlogging/MdcSupplier.java new file mode 100644 index 0000000..ff6c418 --- /dev/null +++ b/src/main/java/de/dm/prom/structuredlogging/MdcSupplier.java @@ -0,0 +1,18 @@ +package de.dm.prom.structuredlogging; + +/** + * Supplier that throws, to be able to handle MDC Context that throw one checked Exception + * + * @param return value of context + * @param thrown checked Exception + */ +public interface MdcSupplier { + /** + * callback to run with context + * + * @return specified return value + * + * @throws E thrown checked Exception + */ + T get() throws E; +} diff --git a/src/test/java/de/dm/prom/structuredlogging/MdcContextUnitTest.java b/src/test/java/de/dm/prom/structuredlogging/MdcContextUnitTest.java index f4acfec..64f85c1 100644 --- a/src/test/java/de/dm/prom/structuredlogging/MdcContextUnitTest.java +++ b/src/test/java/de/dm/prom/structuredlogging/MdcContextUnitTest.java @@ -6,6 +6,7 @@ import de.dm.infrastructure.logcapture.LogCapture; import lombok.extern.slf4j.Slf4j; import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.Nested; import org.junit.jupiter.api.Test; import org.junit.jupiter.api.extension.RegisterExtension; import org.slf4j.MDC; @@ -15,8 +16,10 @@ import static de.dm.infrastructure.logcapture.ExpectedException.exception; import static de.dm.infrastructure.logcapture.LogExpectation.error; import static de.dm.infrastructure.logcapture.LogExpectation.warn; +import static de.dm.prom.structuredlogging.MdcContext.mdc; import static de.dm.prom.structuredlogging.StructuredMdcJsonProvider.JSON_PREFIX; import static org.assertj.core.api.Assertions.assertThat; +import static org.assertj.core.api.Assertions.fail; import static org.mockito.Mockito.mock; import static org.mockito.Mockito.when; @@ -48,27 +51,167 @@ void resetMdc() { MdcContext.resetGlobalObjectMapper(); } - @Test - void createSampleContextWithContextId() throws IOException { - try (MdcContext c = MdcContext.of(ExampleBeanKeySupplier.class, ExampleBean.getExample())) { - assertMdcFieldContentIsCorrect("example_bean", SAMPLE_BEAN_JSON); + @Nested + class ContextId { + @Test + void withTryBlock() throws IOException { + try (MdcContext c = MdcContext.of(ExampleBeanKeySupplier.class, ExampleBean.getExample())) { + assertMdcFieldContentIsCorrect("example_bean", SAMPLE_BEAN_JSON); + } + } + + @Test + void withRunnable() throws IOException { + mdc(ExampleBeanKeySupplier.class, ExampleBean.getExample(), () -> + assertMdcFieldContentIsCorrect("example_bean", SAMPLE_BEAN_JSON)); + } + + @Test + void withThrowingRunnable() { + try { + mdc(ExampleBeanKeySupplier.class, ExampleBean.getExample(), () -> { + assertMdcFieldContentIsCorrect("example_bean", SAMPLE_BEAN_JSON); + throwIOException(); + }); + fail("expected an Exception"); + } catch (IOException e) { + // everything is fine + } + } + + @Test + void withSupplier() throws IOException { + var actual = mdc(ExampleBeanKeySupplier.class, ExampleBean.getExample(), () -> { + assertMdcFieldContentIsCorrect("example_bean", SAMPLE_BEAN_JSON); + return 42; + }); + assertThat(actual).isEqualTo(42); + } + + @Test + void withThrowingSupplier() { + try { + mdc(ExampleBeanKeySupplier.class, ExampleBean.getExample(), () -> { + assertMdcFieldContentIsCorrect("example_bean", SAMPLE_BEAN_JSON); + throwIOException(); + return 42; + }); + fail("expected an Exception"); + } catch (IOException e) { + // everything is fine + } } } - @Test - void createSampleContextWithClassOnly() throws IOException { - try (MdcContext c = MdcContext.of(ExampleBean.getExample())) { - assertMdcFieldContentIsCorrect("ExampleBean", SAMPLE_BEAN_JSON); + @Nested + class ClassOnly { + @Test + void withTryBlock() throws IOException { + try (MdcContext c = MdcContext.of(ExampleBean.getExample())) { + assertMdcFieldContentIsCorrect("ExampleBean", SAMPLE_BEAN_JSON); + } + } + + @Test + void withRunnable() throws IOException { + mdc(ExampleBean.getExample(), () -> + assertMdcFieldContentIsCorrect("ExampleBean", SAMPLE_BEAN_JSON)); + } + + @Test + void withThrowingRunnable() { + try { + mdc(ExampleBean.getExample(), () -> { + assertMdcFieldContentIsCorrect("ExampleBean", SAMPLE_BEAN_JSON); + throwIOException(); + }); + fail("expected an Exception"); + } catch (IOException e) { + // everything is fine + } + } + + @Test + void withSupplier() throws IOException { + var actual = mdc(ExampleBean.getExample(), () -> { + assertMdcFieldContentIsCorrect("ExampleBean", SAMPLE_BEAN_JSON); + return 42; + }); + assertThat(actual).isEqualTo(42); + } + + @Test + void withThrowingSupplier() { + try { + mdc(ExampleBean.getExample(), () -> { + assertMdcFieldContentIsCorrect("ExampleBean", SAMPLE_BEAN_JSON); + throwIOException(); + return 42; + }); + fail("expected an Exception"); + } catch (IOException e) { + // everything is fine + } } } - @Test - void createSampleContextWithKey() throws IOException { - try (MdcContext c = MdcContext.of("explicit_key", ExampleBean.getExample())) { - assertMdcFieldContentIsCorrect("explicit_key", SAMPLE_BEAN_JSON); + @Nested + class KeyFromString { + @Test + void withTryBlock() throws IOException { + try (MdcContext c = MdcContext.of("explicit_key", ExampleBean.getExample())) { + assertMdcFieldContentIsCorrect("explicit_key", SAMPLE_BEAN_JSON); + } + } + + @Test + void withRunnable() throws IOException { + mdc("explicit_key", ExampleBean.getExample(), () -> + assertMdcFieldContentIsCorrect("explicit_key", SAMPLE_BEAN_JSON)); + } + + @Test + void withThrowingRunnable() { + try { + mdc("explicit_key", ExampleBean.getExample(), () -> { + assertMdcFieldContentIsCorrect("explicit_key", SAMPLE_BEAN_JSON); + throwIOException(); + }); + fail("expected an Exception"); + } catch (IOException e) { + // everything is fine + } + } + + @Test + void withSupplier() throws IOException { + var actual = mdc("explicit_key", ExampleBean.getExample(), () -> { + assertMdcFieldContentIsCorrect("explicit_key", SAMPLE_BEAN_JSON); + return 42; + }); + assertThat(actual).isEqualTo(42); + } + + @Test + void withThrowingSupplier() { + try { + mdc("explicit_key", ExampleBean.getExample(), () -> { + assertMdcFieldContentIsCorrect("explicit_key", SAMPLE_BEAN_JSON); + throwIOException(); + return 42; + }); + fail("expected an Exception"); + } catch (IOException e) { + // everything is fine + } } } + private static void throwIOException() throws IOException { + throw new IOException("not really an IOException, just an example"); + } + + @Test void customObjectMapperIsUsedAndReset() throws IOException { ObjectMapper customObjectMapper = mock(ObjectMapper.class); diff --git a/src/test/java/de/dm/prom/structuredlogging/StructuredMdcJsonProviderUnitTest.java b/src/test/java/de/dm/prom/structuredlogging/StructuredMdcJsonProviderUnitTest.java index 6d15ade..b31e7dc 100644 --- a/src/test/java/de/dm/prom/structuredlogging/StructuredMdcJsonProviderUnitTest.java +++ b/src/test/java/de/dm/prom/structuredlogging/StructuredMdcJsonProviderUnitTest.java @@ -1,7 +1,8 @@ package de.dm.prom.structuredlogging; import ch.qos.logback.classic.Logger; -import ch.qos.logback.classic.util.ContextInitializer; +import ch.qos.logback.classic.LoggerContext; +import ch.qos.logback.classic.joran.JoranConfigurator; import ch.qos.logback.core.Appender; import ch.qos.logback.core.joran.spi.JoranException; import com.fasterxml.jackson.databind.JsonNode; @@ -26,7 +27,7 @@ // LogCapture is not applicable here because the actual output format of the log is relevant @Slf4j class StructuredMdcJsonProviderUnitTest { - private static String SAMPLE_LOGSTASH_JSON_LOG = "{\"@version\":\"1\"," + + private static final String SAMPLE_LOGSTASH_JSON_LOG = "{\"@version\":\"1\"," + "\"message\":\"something in which the ExampleBean context is relevant\"," + "\"logger_name\":\"de.dm.prom.structuredlogging.StructuredMdcJsonProviderUnitTest\"," + "\"thread_name\":\"main\"," + @@ -51,14 +52,16 @@ class StructuredMdcJsonProviderUnitTest { "\"yearMonth\":\"2000-08\"," + "\"zonedDateTime\":\"2019-01-01T13:37Z[UTC]\"}}"; - private Logger rootLogger = (Logger) LoggerFactory.getLogger(Logger.ROOT_LOGGER_NAME); + private final Logger rootLogger = (Logger) LoggerFactory.getLogger(Logger.ROOT_LOGGER_NAME); @BeforeEach void setupLogback() throws FileNotFoundException, JoranException { rootLogger.iteratorForAppenders().forEachRemaining(Appender::stop); - new ContextInitializer(rootLogger.getLoggerContext()) - .configureByResource(ResourceUtils.getURL("src/test/resources/logback-stdout-json.xml")); + LoggerContext context = (LoggerContext) LoggerFactory.getILoggerFactory(); + JoranConfigurator configurator = new JoranConfigurator(); + configurator.setContext(context); + configurator.doConfigure(ResourceUtils.getURL("src/test/resources/logback-stdout-json.xml")); } @AfterEach