From 45ba3bfa25120d07d06c5df4a57dc9c3e57d5239 Mon Sep 17 00:00:00 2001 From: Olivia Kotsopoulos Date: Wed, 28 Feb 2024 15:35:03 -0500 Subject: [PATCH 01/10] Populate MDC for flight and its steps Wrap flight thread execution so that flight threads are context-aware. Logs emitted during a flight thread now have the context from the calling thread, along with flight-specific context (flight ID and class). Logs emitted during the execution of a step additionally include step-specific context (step class, direction, and index). Handles the case where a flight thread spawns a child flight by intentionally cleaning any leftover step-specific context from the calling thread. Drive-by: now that we include flight ID and class on all flight logs in the MDC, we can trim down the dismal failure log line. --- .../bio/terra/stairway/impl/FlightRunner.java | 10 +-- .../bio/terra/stairway/impl/MdcHelper.java | 73 +++++++++++++++++++ .../bio/terra/stairway/impl/StairwayImpl.java | 4 +- 3 files changed, 80 insertions(+), 7 deletions(-) create mode 100644 stairway/src/main/java/bio/terra/stairway/impl/MdcHelper.java diff --git a/stairway/src/main/java/bio/terra/stairway/impl/FlightRunner.java b/stairway/src/main/java/bio/terra/stairway/impl/FlightRunner.java index 96a61f7..e867b6f 100644 --- a/stairway/src/main/java/bio/terra/stairway/impl/FlightRunner.java +++ b/stairway/src/main/java/bio/terra/stairway/impl/FlightRunner.java @@ -144,11 +144,9 @@ private FlightStatus fly() throws InterruptedException { // the UNDO in the first place. flightDao.step(flightContext); logger.error( - "DISMAL FAILURE: non-retry-able error during undo. Flight: {}({}) Step: {}({})", - flightContext.getFlightId(), - flightContext.getFlightClassName(), - flightContext.getStepIndex(), - flightContext.getStepClassName()); + "{} (index {}) experienced DISMAL FAILURE: non-retryable error on undo", + flightContext.getStepClassName(), + flightContext.getStepIndex()); } catch (InterruptedException ex) { // Interrupted exception - we assume this means that the thread pool is shutting down and @@ -242,6 +240,7 @@ private StepResult stepWithRetry() throws InterruptedException, StairwayExecutio // Retry loop do { try { + MdcHelper.addStepContextToMdc(flightContext); // Do or undo based on direction we are headed hookWrapper.startStep(flightContext); @@ -271,6 +270,7 @@ private StepResult stepWithRetry() throws InterruptedException, StairwayExecutio result = new StepResult(stepStatus, ex); } finally { hookWrapper.endStep(flightContext); + MdcHelper.removeStepContextFromMdc(flightContext); } switch (result.getStepStatus()) { diff --git a/stairway/src/main/java/bio/terra/stairway/impl/MdcHelper.java b/stairway/src/main/java/bio/terra/stairway/impl/MdcHelper.java new file mode 100644 index 0000000..3e0c285 --- /dev/null +++ b/stairway/src/main/java/bio/terra/stairway/impl/MdcHelper.java @@ -0,0 +1,73 @@ +package bio.terra.stairway.impl; + +import bio.terra.stairway.FlightContext; +import org.slf4j.MDC; + +import java.util.Map; + +public class MdcHelper { + + /** ID of the flight */ + public static final String FLIGHT_ID_KEY = "flightId"; + + /** Class of the flight */ + public static final String FLIGHT_CLASS_KEY = "flightClass"; + + /** Class of the flight step */ + public static final String FLIGHT_STEP_CLASS_KEY = "flightStepClass"; + + /** Direction of the step (START, DO, SWITCH, or UNDO) */ + public static final String FLIGHT_STEP_DIRECTION_KEY = "flightStepDirection"; + + /** The step's execution order */ + public static final String FLIGHT_STEP_NUMBER_KEY = "flightStepNumber"; + + /** + * @param flightRunner + * @param flightContext + * @return the flightRunner modified to propagate the MDC from the calling thread and flight-specific context to the + * child thread spawned to run the flight. + */ + public static Runnable withMdcAndFlightContext(Runnable flightRunner, FlightContext flightContext) { + // Save the calling thread's context + Map contextMap = MDC.getCopyOfContextMap(); + return () -> { + MDC.setContextMap(contextMap); + // If the calling thread's context contains flight and step context from a parent flight, this will + // be overridden below: + addFlightContextToMdc(flightContext); + removeStepContextFromMdc(flightContext); + try { + flightRunner.run(); + } finally { + // Once the flight is complete, clear MDC + MDC.clear(); + } + }; + } + + private static Map flightContextForMdc(FlightContext context) { + return Map.of( + FLIGHT_ID_KEY, context.getFlightId(), + FLIGHT_CLASS_KEY, context.getFlightClassName()); + } + + private static void addFlightContextToMdc(FlightContext context) { + flightContextForMdc(context).forEach(MDC::put); + } + + private static Map stepContextForMdc(FlightContext context) { + return Map.of( + FLIGHT_STEP_CLASS_KEY, context.getStepClassName(), + FLIGHT_STEP_DIRECTION_KEY, context.getDirection().toString(), + FLIGHT_STEP_NUMBER_KEY, Integer.toString(context.getStepIndex())); + } + + public static void addStepContextToMdc(FlightContext context) { + stepContextForMdc(context).forEach(MDC::put); + } + + public static void removeStepContextFromMdc(FlightContext context) { + stepContextForMdc(context).keySet().forEach(MDC::remove); + } +} diff --git a/stairway/src/main/java/bio/terra/stairway/impl/StairwayImpl.java b/stairway/src/main/java/bio/terra/stairway/impl/StairwayImpl.java index 589ffcf..859e215 100644 --- a/stairway/src/main/java/bio/terra/stairway/impl/StairwayImpl.java +++ b/stairway/src/main/java/bio/terra/stairway/impl/StairwayImpl.java @@ -636,7 +636,7 @@ void recoverReady() throws StairwayException, InterruptedException { /* * Build the FlightRunner object that will execute the flight - * and hand it to the threadPool to run. + * and hand it to the threadPool to run, with MDC populated from the calling thread and flight context. */ private void launchFlight(FlightContextImpl flightContext) { FlightRunner runner = new FlightRunner(flightContext); @@ -649,7 +649,7 @@ private void launchFlight(FlightContextImpl flightContext) { + threadPool.getPoolSize()); } logger.info("Launching flight " + flightContext.flightDesc()); - threadPool.submit(runner); + threadPool.submit(MdcHelper.withMdcAndFlightContext(runner, flightContext)); } HookWrapper getHookWrapper() { From 15f1718070db31acbdba496f7929f81e9c5e61c9 Mon Sep 17 00:00:00 2001 From: Olivia Kotsopoulos Date: Thu, 29 Feb 2024 12:26:34 -0500 Subject: [PATCH 02/10] Cannot call MDC.setContextMap with a null input --- .../src/main/java/bio/terra/stairway/impl/MdcHelper.java | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/stairway/src/main/java/bio/terra/stairway/impl/MdcHelper.java b/stairway/src/main/java/bio/terra/stairway/impl/MdcHelper.java index 3e0c285..4691c2d 100644 --- a/stairway/src/main/java/bio/terra/stairway/impl/MdcHelper.java +++ b/stairway/src/main/java/bio/terra/stairway/impl/MdcHelper.java @@ -4,6 +4,7 @@ import org.slf4j.MDC; import java.util.Map; +import java.util.Optional; public class MdcHelper { @@ -32,9 +33,10 @@ public static Runnable withMdcAndFlightContext(Runnable flightRunner, FlightCont // Save the calling thread's context Map contextMap = MDC.getCopyOfContextMap(); return () -> { - MDC.setContextMap(contextMap); + // Any leftover context on the thread will be fully overwritten: + MDC.setContextMap(Optional.ofNullable(contextMap).orElse(Map.of())); // If the calling thread's context contains flight and step context from a parent flight, this will - // be overridden below: + // be overwritten below: addFlightContextToMdc(flightContext); removeStepContextFromMdc(flightContext); try { From 096711921688494fbdfeb027cba5a630c7a35efa Mon Sep 17 00:00:00 2001 From: Olivia Kotsopoulos Date: Thu, 29 Feb 2024 16:54:26 -0500 Subject: [PATCH 03/10] Add unit tests, spotlessApply In a follow-on PR, will automate spotlessCheck to gate PRs. --- .../groovy/stairway.java-conventions.gradle | 3 +- .../bio/terra/stairway/impl/MdcHelper.java | 111 +++++++------- .../stairway/fixtures/TestFlightContext.java | 145 ++++++++++++++++++ .../terra/stairway/impl/MdcHelperTest.java | 140 +++++++++++++++++ 4 files changed, 341 insertions(+), 58 deletions(-) create mode 100644 stairway/src/test/java/bio/terra/stairway/fixtures/TestFlightContext.java create mode 100644 stairway/src/test/java/bio/terra/stairway/impl/MdcHelperTest.java diff --git a/buildSrc/src/main/groovy/stairway.java-conventions.gradle b/buildSrc/src/main/groovy/stairway.java-conventions.gradle index b7e2994..6c9e6f2 100644 --- a/buildSrc/src/main/groovy/stairway.java-conventions.gradle +++ b/buildSrc/src/main/groovy/stairway.java-conventions.gradle @@ -16,8 +16,7 @@ dependencies { implementation group: 'org.slf4j', name: 'slf4j-api', version: '1.7.36' // For testing - testImplementation group: 'org.junit.jupiter', name: 'junit-jupiter-api', version: '5.9.0' - testImplementation group: 'org.junit.jupiter', name: 'junit-jupiter-engine', version: '5.9.0' + testImplementation group: 'org.junit.jupiter', name: 'junit-jupiter', version: '5.10.2' testImplementation group: 'org.hamcrest', name: 'hamcrest', version: '2.2' testImplementation group: 'ch.qos.logback', name: 'logback-classic', version: '1.4.1' testRuntimeOnly group: 'org.codehaus.groovy', name: 'groovy', version: '3.0.13' diff --git a/stairway/src/main/java/bio/terra/stairway/impl/MdcHelper.java b/stairway/src/main/java/bio/terra/stairway/impl/MdcHelper.java index 4691c2d..bafcbb3 100644 --- a/stairway/src/main/java/bio/terra/stairway/impl/MdcHelper.java +++ b/stairway/src/main/java/bio/terra/stairway/impl/MdcHelper.java @@ -1,75 +1,74 @@ package bio.terra.stairway.impl; import bio.terra.stairway.FlightContext; -import org.slf4j.MDC; - import java.util.Map; import java.util.Optional; +import org.slf4j.MDC; public class MdcHelper { - /** ID of the flight */ - public static final String FLIGHT_ID_KEY = "flightId"; + /** ID of the flight */ + public static final String FLIGHT_ID_KEY = "flightId"; - /** Class of the flight */ - public static final String FLIGHT_CLASS_KEY = "flightClass"; + /** Class of the flight */ + public static final String FLIGHT_CLASS_KEY = "flightClass"; - /** Class of the flight step */ - public static final String FLIGHT_STEP_CLASS_KEY = "flightStepClass"; + /** Class of the flight step */ + public static final String FLIGHT_STEP_CLASS_KEY = "flightStepClass"; - /** Direction of the step (START, DO, SWITCH, or UNDO) */ - public static final String FLIGHT_STEP_DIRECTION_KEY = "flightStepDirection"; + /** Direction of the step (START, DO, SWITCH, or UNDO) */ + public static final String FLIGHT_STEP_DIRECTION_KEY = "flightStepDirection"; - /** The step's execution order */ - public static final String FLIGHT_STEP_NUMBER_KEY = "flightStepNumber"; + /** The step's execution order */ + public static final String FLIGHT_STEP_NUMBER_KEY = "flightStepNumber"; - /** - * @param flightRunner - * @param flightContext - * @return the flightRunner modified to propagate the MDC from the calling thread and flight-specific context to the - * child thread spawned to run the flight. - */ - public static Runnable withMdcAndFlightContext(Runnable flightRunner, FlightContext flightContext) { - // Save the calling thread's context - Map contextMap = MDC.getCopyOfContextMap(); - return () -> { - // Any leftover context on the thread will be fully overwritten: - MDC.setContextMap(Optional.ofNullable(contextMap).orElse(Map.of())); - // If the calling thread's context contains flight and step context from a parent flight, this will - // be overwritten below: - addFlightContextToMdc(flightContext); - removeStepContextFromMdc(flightContext); - try { - flightRunner.run(); - } finally { - // Once the flight is complete, clear MDC - MDC.clear(); - } - }; - } + /** + * @return the flightRunner modified to propagate the MDC from the calling thread and + * flight-specific context to the child thread spawned to run the flight. + */ + public static Runnable withMdcAndFlightContext( + Runnable flightRunner, FlightContext flightContext) { + // Save the calling thread's context + Map contextMap = MDC.getCopyOfContextMap(); + return () -> { + // Any leftover context on the thread will be fully overwritten: + MDC.setContextMap(Optional.ofNullable(contextMap).orElse(Map.of())); + // If the calling thread's context contains flight and step context from a parent flight, this + // will + // be overwritten below: + addFlightContextToMdc(flightContext); + removeStepContextFromMdc(flightContext); + try { + flightRunner.run(); + } finally { + // Once the flight is complete, clear MDC + MDC.clear(); + } + }; + } - private static Map flightContextForMdc(FlightContext context) { - return Map.of( - FLIGHT_ID_KEY, context.getFlightId(), - FLIGHT_CLASS_KEY, context.getFlightClassName()); - } + private static Map flightContextForMdc(FlightContext context) { + return Map.of( + FLIGHT_ID_KEY, context.getFlightId(), + FLIGHT_CLASS_KEY, context.getFlightClassName()); + } - private static void addFlightContextToMdc(FlightContext context) { - flightContextForMdc(context).forEach(MDC::put); - } + private static void addFlightContextToMdc(FlightContext context) { + flightContextForMdc(context).forEach(MDC::put); + } - private static Map stepContextForMdc(FlightContext context) { - return Map.of( - FLIGHT_STEP_CLASS_KEY, context.getStepClassName(), - FLIGHT_STEP_DIRECTION_KEY, context.getDirection().toString(), - FLIGHT_STEP_NUMBER_KEY, Integer.toString(context.getStepIndex())); - } + private static Map stepContextForMdc(FlightContext context) { + return Map.of( + FLIGHT_STEP_CLASS_KEY, context.getStepClassName(), + FLIGHT_STEP_DIRECTION_KEY, context.getDirection().toString(), + FLIGHT_STEP_NUMBER_KEY, Integer.toString(context.getStepIndex())); + } - public static void addStepContextToMdc(FlightContext context) { - stepContextForMdc(context).forEach(MDC::put); - } + public static void addStepContextToMdc(FlightContext context) { + stepContextForMdc(context).forEach(MDC::put); + } - public static void removeStepContextFromMdc(FlightContext context) { - stepContextForMdc(context).keySet().forEach(MDC::remove); - } + public static void removeStepContextFromMdc(FlightContext context) { + stepContextForMdc(context).keySet().forEach(MDC::remove); + } } diff --git a/stairway/src/test/java/bio/terra/stairway/fixtures/TestFlightContext.java b/stairway/src/test/java/bio/terra/stairway/fixtures/TestFlightContext.java new file mode 100644 index 0000000..18616b2 --- /dev/null +++ b/stairway/src/test/java/bio/terra/stairway/fixtures/TestFlightContext.java @@ -0,0 +1,145 @@ +package bio.terra.stairway.fixtures; + +import bio.terra.stairway.Direction; +import bio.terra.stairway.FlightContext; +import bio.terra.stairway.FlightMap; +import bio.terra.stairway.FlightStatus; +import bio.terra.stairway.ProgressMeter; +import bio.terra.stairway.Stairway; +import bio.terra.stairway.StepResult; +import java.util.List; +import java.util.UUID; + +/** + * A flight context implementation for use in unit tests to avoid running Stairway flights, with + * additional helper methods for modification. + */ +public class TestFlightContext implements FlightContext { + + private String flightId = "flightId" + UUID.randomUUID(); + private String flightClassName = "flightClass" + UUID.randomUUID(); + private FlightMap inputParameters = new FlightMap(); + private FlightMap workingMap = new FlightMap(); + private int stepIndex = 0; + private FlightStatus flightStatus = FlightStatus.QUEUED; + private Direction direction = Direction.DO; + private String stepClassName = "stepClass" + UUID.randomUUID(); + + @Override + public Object getApplicationContext() { + return null; + } + + @Override + public String getFlightId() { + return flightId; + } + + public TestFlightContext flightId(String flightId) { + this.flightId = flightId; + return this; + } + + @Override + public String getFlightClassName() { + return flightClassName; + } + + public TestFlightContext flightClassName(String flightClassName) { + this.flightClassName = flightClassName; + return this; + } + + @Override + public FlightMap getInputParameters() { + return inputParameters; + } + + public TestFlightContext inputParameters(FlightMap inputParameters) { + this.inputParameters = inputParameters; + return this; + } + + @Override + public FlightMap getWorkingMap() { + return workingMap; + } + + @Override + public int getStepIndex() { + return stepIndex; + } + + public TestFlightContext stepIndex(int stepIndex) { + this.stepIndex = stepIndex; + return this; + } + + @Override + public FlightStatus getFlightStatus() { + return flightStatus; + } + + public TestFlightContext flightStatus(FlightStatus flightStatus) { + this.flightStatus = flightStatus; + return this; + } + + @Override + public boolean isRerun() { + return false; + } + + @Override + public Direction getDirection() { + return direction; + } + + public TestFlightContext direction(Direction direction) { + this.direction = direction; + return this; + } + + @Override + public StepResult getResult() { + return null; + } + + @Override + public Stairway getStairway() { + return null; + } + + @Override + public List getStepClassNames() { + return null; + } + + @Override + public String getStepClassName() { + return stepClassName; + } + + public TestFlightContext stepClassName(String stepClassName) { + this.stepClassName = stepClassName; + return this; + } + + @Override + public String prettyStepState() { + return null; + } + + @Override + public String flightDesc() { + return null; + } + + @Override + public ProgressMeter getProgressMeter(String name) { + return null; + } + + @Override + public void setProgressMeter(String name, long v1, long v2) {} +} diff --git a/stairway/src/test/java/bio/terra/stairway/impl/MdcHelperTest.java b/stairway/src/test/java/bio/terra/stairway/impl/MdcHelperTest.java new file mode 100644 index 0000000..4ec14a7 --- /dev/null +++ b/stairway/src/test/java/bio/terra/stairway/impl/MdcHelperTest.java @@ -0,0 +1,140 @@ +package bio.terra.stairway.impl; + +import static org.hamcrest.MatcherAssert.assertThat; +import static org.hamcrest.Matchers.equalTo; + +import bio.terra.stairway.Direction; +import bio.terra.stairway.fixtures.TestFlightContext; +import java.util.HashMap; +import java.util.Map; +import java.util.UUID; +import java.util.stream.Stream; +import org.junit.jupiter.api.BeforeEach; +import org.junit.jupiter.api.Tag; +import org.junit.jupiter.params.ParameterizedTest; +import org.junit.jupiter.params.provider.MethodSource; +import org.slf4j.MDC; + +@Tag("unit") +public class MdcHelperTest { + private static final Map FOO_BAR = Map.of("foo", "bar"); + private static final String FLIGHT_ID = "flightId" + UUID.randomUUID(); + private static final String FLIGHT_CLASS = "flightClass" + UUID.randomUUID(); + private static final Map FLIGHT_MDC = + Map.of(MdcHelper.FLIGHT_ID_KEY, FLIGHT_ID, MdcHelper.FLIGHT_CLASS_KEY, FLIGHT_CLASS); + private static final int STEP_INDEX = 2; + private static final Direction STEP_DIRECTION = Direction.DO; + private static final String STEP_CLASS = "stepClass" + UUID.randomUUID(); + private static final Map STEP_MDC = + Map.of( + MdcHelper.FLIGHT_STEP_NUMBER_KEY, + Integer.toString(STEP_INDEX), + MdcHelper.FLIGHT_STEP_DIRECTION_KEY, + STEP_DIRECTION.toString(), + MdcHelper.FLIGHT_STEP_CLASS_KEY, + STEP_CLASS); + + private TestFlightContext flightContext; + + @BeforeEach + void beforeEach() { + MDC.clear(); + flightContext = + new TestFlightContext() + .flightId(FLIGHT_ID) + .flightClassName(FLIGHT_CLASS) + .stepIndex(STEP_INDEX) + .direction(STEP_DIRECTION) + .stepClassName(STEP_CLASS); + } + + static Stream> initialContext() { + return Stream.of(null, Map.of(), FOO_BAR); + } + + @ParameterizedTest + @MethodSource("initialContext") + void withMdcAndFlightContext(Map initialContext) { + var expectedMdc = new HashMap<>(FLIGHT_MDC); + if (initialContext != null) { + MDC.setContextMap(initialContext); + expectedMdc.putAll(initialContext); + } + + Runnable runnable = + () -> + assertThat( + "Calling thread's context with new flight context", + MDC.getCopyOfContextMap(), + equalTo(expectedMdc)); + MdcHelper.withMdcAndFlightContext(runnable, flightContext).run(); + } + + @ParameterizedTest + @MethodSource("initialContext") + void withMdcAndFlightContext_subflight(Map initialContext) { + var expectedParentFlightMdc = new HashMap<>(FLIGHT_MDC); + + var childFlightId = "childFlightId"; + var childFlightClass = "childFlightClass"; + + var childFlightContext = + new TestFlightContext().flightId(childFlightId).flightClassName(childFlightClass); + var expectedChildFlightMdc = new HashMap<>(); + expectedChildFlightMdc.put(MdcHelper.FLIGHT_ID_KEY, childFlightId); + expectedChildFlightMdc.put(MdcHelper.FLIGHT_CLASS_KEY, childFlightClass); + + if (initialContext != null) { + MDC.setContextMap(initialContext); + expectedParentFlightMdc.putAll(initialContext); + expectedChildFlightMdc.putAll(initialContext); + } + + Runnable parentFlight = + () -> { + assertThat( + "Calling thread's context with parent flight context", + MDC.getCopyOfContextMap(), + equalTo(expectedParentFlightMdc)); + // If a child flight is launched within a step in a parent flight, the calling thread's + // context would also + // contain step-specific context that should be cleared for logs emitted by the child + // flight. + MdcHelper.addStepContextToMdc(flightContext); + Runnable childFlight = + () -> + assertThat( + "Calling thread's context with child flight context", + MDC.getCopyOfContextMap(), + equalTo(expectedChildFlightMdc)); + MdcHelper.withMdcAndFlightContext(childFlight, childFlightContext).run(); + }; + + MdcHelper.withMdcAndFlightContext(parentFlight, flightContext).run(); + } + + @ParameterizedTest + @MethodSource("initialContext") + void addAndRemoveStepContextFromMdc(Map initialContext) { + var expectedAddStepMdc = new HashMap<>(); + var expectedRemoveStepMdc = new HashMap<>(); + if (initialContext != null) { + MDC.setContextMap(initialContext); + expectedAddStepMdc.putAll(initialContext); + expectedRemoveStepMdc.putAll(initialContext); + } + expectedAddStepMdc.putAll(STEP_MDC); + + MdcHelper.addStepContextToMdc(flightContext); + assertThat( + "Initial context with new step context", + MDC.getCopyOfContextMap(), + equalTo(expectedAddStepMdc)); + + MdcHelper.removeStepContextFromMdc(flightContext); + assertThat( + "Initial context without step context", + MDC.getCopyOfContextMap(), + equalTo(expectedRemoveStepMdc)); + } +} From 6668262804f9cd07be73e76d0556b8dcd6872f9e Mon Sep 17 00:00:00 2001 From: Olivia Kotsopoulos Date: Thu, 29 Feb 2024 17:42:21 -0500 Subject: [PATCH 04/10] Update README to highlight MDC additions And some other formatting and documentation changes. --- README.md | 10 ++++++++++ .../main/java/bio/terra/stairway/impl/MdcHelper.java | 6 ++++-- .../java/bio/terra/stairway/impl/MdcHelperTest.java | 5 ++--- 3 files changed, 16 insertions(+), 5 deletions(-) diff --git a/README.md b/README.md index 2cf388d..d21aad4 100644 --- a/README.md +++ b/README.md @@ -93,6 +93,16 @@ Stairway is designed to provide atomic operations for one instance of one servic global or cross-service state. Therefore, it is up to the application or service to implement concurrency control on its objects. +### Context Awareness and Logs +Stairway leverages the underlying logging system's mapped diagnostic context (MDC) if available. + +MDC manages contextual information on a per-thread basis: as Stairway submits a Flight for processing, +it **passes along the MDC of the calling thread** so that context isn't lost. It also further populates +the MDC with **flight-specific context** for the duration of the flight's execution on the thread, +and **step-specific context** for the duration of each step's execution. + +For more information on MDC, please see [Logback's MDC manual](https://logback.qos.ch/manual/mdc.html). + # TODOs * Add a section on clusters, queuing, failure, and recovery * Add a section - perhaps in DEVELOPMENT.md describing the schema diff --git a/stairway/src/main/java/bio/terra/stairway/impl/MdcHelper.java b/stairway/src/main/java/bio/terra/stairway/impl/MdcHelper.java index bafcbb3..f3143a5 100644 --- a/stairway/src/main/java/bio/terra/stairway/impl/MdcHelper.java +++ b/stairway/src/main/java/bio/terra/stairway/impl/MdcHelper.java @@ -5,6 +5,9 @@ import java.util.Optional; import org.slf4j.MDC; +/** + * Utility methods to make Stairway flight runnables context-aware, using mapped diagnostic context (MDC). + */ public class MdcHelper { /** ID of the flight */ @@ -34,8 +37,7 @@ public static Runnable withMdcAndFlightContext( // Any leftover context on the thread will be fully overwritten: MDC.setContextMap(Optional.ofNullable(contextMap).orElse(Map.of())); // If the calling thread's context contains flight and step context from a parent flight, this - // will - // be overwritten below: + // will be overwritten below: addFlightContextToMdc(flightContext); removeStepContextFromMdc(flightContext); try { diff --git a/stairway/src/test/java/bio/terra/stairway/impl/MdcHelperTest.java b/stairway/src/test/java/bio/terra/stairway/impl/MdcHelperTest.java index 4ec14a7..c017513 100644 --- a/stairway/src/test/java/bio/terra/stairway/impl/MdcHelperTest.java +++ b/stairway/src/test/java/bio/terra/stairway/impl/MdcHelperTest.java @@ -97,9 +97,8 @@ void withMdcAndFlightContext_subflight(Map initialContext) { MDC.getCopyOfContextMap(), equalTo(expectedParentFlightMdc)); // If a child flight is launched within a step in a parent flight, the calling thread's - // context would also - // contain step-specific context that should be cleared for logs emitted by the child - // flight. + // context would also contain step-specific context that should be cleared for logs + // emitted by the child flight. MdcHelper.addStepContextToMdc(flightContext); Runnable childFlight = () -> From 4ac56faac948e4348d2dac6ffd08c0ad88e67dea Mon Sep 17 00:00:00 2001 From: Olivia Kotsopoulos Date: Thu, 29 Feb 2024 17:53:32 -0500 Subject: [PATCH 05/10] MdcHelper, MdcHelperTest needn't be public The MdcHelper methods are only meant to be called within the Stairway implementation package. --- .../bio/terra/stairway/impl/MdcHelper.java | 22 +++++++++---------- .../terra/stairway/impl/MdcHelperTest.java | 2 +- 2 files changed, 12 insertions(+), 12 deletions(-) diff --git a/stairway/src/main/java/bio/terra/stairway/impl/MdcHelper.java b/stairway/src/main/java/bio/terra/stairway/impl/MdcHelper.java index f3143a5..00ce6d0 100644 --- a/stairway/src/main/java/bio/terra/stairway/impl/MdcHelper.java +++ b/stairway/src/main/java/bio/terra/stairway/impl/MdcHelper.java @@ -6,31 +6,31 @@ import org.slf4j.MDC; /** - * Utility methods to make Stairway flight runnables context-aware, using mapped diagnostic context (MDC). + * Utility methods to make Stairway flight runnables context-aware, using mapped diagnostic context + * (MDC). */ -public class MdcHelper { +class MdcHelper { /** ID of the flight */ - public static final String FLIGHT_ID_KEY = "flightId"; + static final String FLIGHT_ID_KEY = "flightId"; /** Class of the flight */ - public static final String FLIGHT_CLASS_KEY = "flightClass"; + static final String FLIGHT_CLASS_KEY = "flightClass"; /** Class of the flight step */ - public static final String FLIGHT_STEP_CLASS_KEY = "flightStepClass"; + static final String FLIGHT_STEP_CLASS_KEY = "flightStepClass"; /** Direction of the step (START, DO, SWITCH, or UNDO) */ - public static final String FLIGHT_STEP_DIRECTION_KEY = "flightStepDirection"; + static final String FLIGHT_STEP_DIRECTION_KEY = "flightStepDirection"; /** The step's execution order */ - public static final String FLIGHT_STEP_NUMBER_KEY = "flightStepNumber"; + static final String FLIGHT_STEP_NUMBER_KEY = "flightStepNumber"; /** * @return the flightRunner modified to propagate the MDC from the calling thread and * flight-specific context to the child thread spawned to run the flight. */ - public static Runnable withMdcAndFlightContext( - Runnable flightRunner, FlightContext flightContext) { + static Runnable withMdcAndFlightContext(Runnable flightRunner, FlightContext flightContext) { // Save the calling thread's context Map contextMap = MDC.getCopyOfContextMap(); return () -> { @@ -66,11 +66,11 @@ private static Map stepContextForMdc(FlightContext context) { FLIGHT_STEP_NUMBER_KEY, Integer.toString(context.getStepIndex())); } - public static void addStepContextToMdc(FlightContext context) { + static void addStepContextToMdc(FlightContext context) { stepContextForMdc(context).forEach(MDC::put); } - public static void removeStepContextFromMdc(FlightContext context) { + static void removeStepContextFromMdc(FlightContext context) { stepContextForMdc(context).keySet().forEach(MDC::remove); } } diff --git a/stairway/src/test/java/bio/terra/stairway/impl/MdcHelperTest.java b/stairway/src/test/java/bio/terra/stairway/impl/MdcHelperTest.java index c017513..4ca9640 100644 --- a/stairway/src/test/java/bio/terra/stairway/impl/MdcHelperTest.java +++ b/stairway/src/test/java/bio/terra/stairway/impl/MdcHelperTest.java @@ -16,7 +16,7 @@ import org.slf4j.MDC; @Tag("unit") -public class MdcHelperTest { +class MdcHelperTest { private static final Map FOO_BAR = Map.of("foo", "bar"); private static final String FLIGHT_ID = "flightId" + UUID.randomUUID(); private static final String FLIGHT_CLASS = "flightClass" + UUID.randomUUID(); From 37533fdbac94512bf4373b2f75960b94ddc4453a Mon Sep 17 00:00:00 2001 From: Olivia Kotsopoulos Date: Fri, 1 Mar 2024 16:29:41 -0500 Subject: [PATCH 06/10] Code reorg: flight context-awareness moved to StairwayThreadPool Because Stairway flights are submitted to the StairwayThreadPool for execution, it makes more sense to update the threadpool to wrap task submission to handle setting up and clearing flight context for the duration of the flight run on the child thread. MdcHelper becomes MdcUtils, now a home for less involved utility methods for modifying the MDC. Expanded tests accordingly: StairwayThreadPool did not previously have targeted unit tests. --- .../bio/terra/stairway/impl/FlightRunner.java | 4 +- .../bio/terra/stairway/impl/MdcHelper.java | 76 ---------- .../bio/terra/stairway/impl/MdcUtils.java | 74 ++++++++++ .../bio/terra/stairway/impl/StairwayImpl.java | 11 +- .../stairway/impl/StairwayThreadPool.java | 57 ++++++-- .../{MdcHelperTest.java => MdcUtilsTest.java} | 73 +++------- .../stairway/impl/StairwayThreadPoolTest.java | 137 ++++++++++++++++++ 7 files changed, 281 insertions(+), 151 deletions(-) delete mode 100644 stairway/src/main/java/bio/terra/stairway/impl/MdcHelper.java create mode 100644 stairway/src/main/java/bio/terra/stairway/impl/MdcUtils.java rename stairway/src/test/java/bio/terra/stairway/impl/{MdcHelperTest.java => MdcUtilsTest.java} (51%) create mode 100644 stairway/src/test/java/bio/terra/stairway/impl/StairwayThreadPoolTest.java diff --git a/stairway/src/main/java/bio/terra/stairway/impl/FlightRunner.java b/stairway/src/main/java/bio/terra/stairway/impl/FlightRunner.java index e867b6f..ee79343 100644 --- a/stairway/src/main/java/bio/terra/stairway/impl/FlightRunner.java +++ b/stairway/src/main/java/bio/terra/stairway/impl/FlightRunner.java @@ -240,7 +240,7 @@ private StepResult stepWithRetry() throws InterruptedException, StairwayExecutio // Retry loop do { try { - MdcHelper.addStepContextToMdc(flightContext); + MdcUtils.addStepContextToMdc(flightContext); // Do or undo based on direction we are headed hookWrapper.startStep(flightContext); @@ -270,7 +270,7 @@ private StepResult stepWithRetry() throws InterruptedException, StairwayExecutio result = new StepResult(stepStatus, ex); } finally { hookWrapper.endStep(flightContext); - MdcHelper.removeStepContextFromMdc(flightContext); + MdcUtils.removeStepContextFromMdc(flightContext); } switch (result.getStepStatus()) { diff --git a/stairway/src/main/java/bio/terra/stairway/impl/MdcHelper.java b/stairway/src/main/java/bio/terra/stairway/impl/MdcHelper.java deleted file mode 100644 index 00ce6d0..0000000 --- a/stairway/src/main/java/bio/terra/stairway/impl/MdcHelper.java +++ /dev/null @@ -1,76 +0,0 @@ -package bio.terra.stairway.impl; - -import bio.terra.stairway.FlightContext; -import java.util.Map; -import java.util.Optional; -import org.slf4j.MDC; - -/** - * Utility methods to make Stairway flight runnables context-aware, using mapped diagnostic context - * (MDC). - */ -class MdcHelper { - - /** ID of the flight */ - static final String FLIGHT_ID_KEY = "flightId"; - - /** Class of the flight */ - static final String FLIGHT_CLASS_KEY = "flightClass"; - - /** Class of the flight step */ - static final String FLIGHT_STEP_CLASS_KEY = "flightStepClass"; - - /** Direction of the step (START, DO, SWITCH, or UNDO) */ - static final String FLIGHT_STEP_DIRECTION_KEY = "flightStepDirection"; - - /** The step's execution order */ - static final String FLIGHT_STEP_NUMBER_KEY = "flightStepNumber"; - - /** - * @return the flightRunner modified to propagate the MDC from the calling thread and - * flight-specific context to the child thread spawned to run the flight. - */ - static Runnable withMdcAndFlightContext(Runnable flightRunner, FlightContext flightContext) { - // Save the calling thread's context - Map contextMap = MDC.getCopyOfContextMap(); - return () -> { - // Any leftover context on the thread will be fully overwritten: - MDC.setContextMap(Optional.ofNullable(contextMap).orElse(Map.of())); - // If the calling thread's context contains flight and step context from a parent flight, this - // will be overwritten below: - addFlightContextToMdc(flightContext); - removeStepContextFromMdc(flightContext); - try { - flightRunner.run(); - } finally { - // Once the flight is complete, clear MDC - MDC.clear(); - } - }; - } - - private static Map flightContextForMdc(FlightContext context) { - return Map.of( - FLIGHT_ID_KEY, context.getFlightId(), - FLIGHT_CLASS_KEY, context.getFlightClassName()); - } - - private static void addFlightContextToMdc(FlightContext context) { - flightContextForMdc(context).forEach(MDC::put); - } - - private static Map stepContextForMdc(FlightContext context) { - return Map.of( - FLIGHT_STEP_CLASS_KEY, context.getStepClassName(), - FLIGHT_STEP_DIRECTION_KEY, context.getDirection().toString(), - FLIGHT_STEP_NUMBER_KEY, Integer.toString(context.getStepIndex())); - } - - static void addStepContextToMdc(FlightContext context) { - stepContextForMdc(context).forEach(MDC::put); - } - - static void removeStepContextFromMdc(FlightContext context) { - stepContextForMdc(context).keySet().forEach(MDC::remove); - } -} diff --git a/stairway/src/main/java/bio/terra/stairway/impl/MdcUtils.java b/stairway/src/main/java/bio/terra/stairway/impl/MdcUtils.java new file mode 100644 index 0000000..0bd0833 --- /dev/null +++ b/stairway/src/main/java/bio/terra/stairway/impl/MdcUtils.java @@ -0,0 +1,74 @@ +package bio.terra.stairway.impl; + +import bio.terra.stairway.FlightContext; +import java.util.Map; +import org.slf4j.MDC; + +/** + * Utility methods to make Stairway flight runnables context-aware, using mapped diagnostic context + * (MDC). + */ +class MdcUtils { + + /** ID of the flight */ + static final String FLIGHT_ID_KEY = "flightId"; + + /** Class of the flight */ + static final String FLIGHT_CLASS_KEY = "flightClass"; + + /** Class of the flight step */ + static final String FLIGHT_STEP_CLASS_KEY = "flightStepClass"; + + /** Direction of the step (START, DO, SWITCH, or UNDO) */ + static final String FLIGHT_STEP_DIRECTION_KEY = "flightStepDirection"; + + /** The step's execution order */ + static final String FLIGHT_STEP_NUMBER_KEY = "flightStepNumber"; + + /** + * Null-safe utility method for overwriting the current thread's MDC. + * + * @param context to set as MDC, if null then MDC will be cleared. + */ + static void overwriteContext(Map context) { + if (context == null) { + MDC.clear(); + } else { + MDC.setContextMap(context); + } + } + + private static Map flightContextForMdc(FlightContext context) { + return Map.of( + FLIGHT_ID_KEY, context.getFlightId(), + FLIGHT_CLASS_KEY, context.getFlightClassName()); + } + + /** + * Supplement the current thread's MDC with flight-specific context, meant to persist for the + * duration of this flight's execution on the thread. + */ + static void addFlightContextToMdc(FlightContext flightContext) { + flightContextForMdc(flightContext).forEach(MDC::put); + } + + private static Map stepContextForMdc(FlightContext flightContext) { + return Map.of( + FLIGHT_STEP_CLASS_KEY, flightContext.getStepClassName(), + FLIGHT_STEP_DIRECTION_KEY, flightContext.getDirection().toString(), + FLIGHT_STEP_NUMBER_KEY, Integer.toString(flightContext.getStepIndex())); + } + + /** + * Supplement the current thread's MDC with step-specific context, meant to persist for the + * duration of this step's current attempt on the thread. + */ + static void addStepContextToMdc(FlightContext flightContext) { + stepContextForMdc(flightContext).forEach(MDC::put); + } + + /** Remove any step-specific context from the current thread's MDC. */ + static void removeStepContextFromMdc(FlightContext flightContext) { + stepContextForMdc(flightContext).keySet().forEach(MDC::remove); + } +} diff --git a/stairway/src/main/java/bio/terra/stairway/impl/StairwayImpl.java b/stairway/src/main/java/bio/terra/stairway/impl/StairwayImpl.java index 859e215..7adc62a 100644 --- a/stairway/src/main/java/bio/terra/stairway/impl/StairwayImpl.java +++ b/stairway/src/main/java/bio/terra/stairway/impl/StairwayImpl.java @@ -25,7 +25,6 @@ import java.time.Duration; import java.util.List; import java.util.UUID; -import java.util.concurrent.LinkedBlockingQueue; import java.util.concurrent.ScheduledExecutorService; import java.util.concurrent.ScheduledThreadPoolExecutor; import java.util.concurrent.ThreadPoolExecutor; @@ -211,13 +210,7 @@ public void recoverStairway(String stairwayName) throws InterruptedException { } private void configureThreadPools() { - threadPool = - new StairwayThreadPool( - maxParallelFlights, - maxParallelFlights, - 0L, - TimeUnit.MILLISECONDS, - new LinkedBlockingQueue()); + threadPool = new StairwayThreadPool(maxParallelFlights); scheduledPool = new ScheduledThreadPoolExecutor(SCHEDULED_POOL_CORE_THREADS); // If we have retention settings then set up the regular flight cleaner @@ -649,7 +642,7 @@ private void launchFlight(FlightContextImpl flightContext) { + threadPool.getPoolSize()); } logger.info("Launching flight " + flightContext.flightDesc()); - threadPool.submit(MdcHelper.withMdcAndFlightContext(runner, flightContext)); + threadPool.submitWithMdcAndFlightContext(runner, flightContext); } HookWrapper getHookWrapper() { diff --git a/stairway/src/main/java/bio/terra/stairway/impl/StairwayThreadPool.java b/stairway/src/main/java/bio/terra/stairway/impl/StairwayThreadPool.java index c014e90..9f976b9 100644 --- a/stairway/src/main/java/bio/terra/stairway/impl/StairwayThreadPool.java +++ b/stairway/src/main/java/bio/terra/stairway/impl/StairwayThreadPool.java @@ -1,23 +1,27 @@ package bio.terra.stairway.impl; -import java.util.concurrent.BlockingQueue; +import bio.terra.stairway.FlightContext; +import java.util.Map; +import java.util.concurrent.Future; +import java.util.concurrent.LinkedBlockingQueue; import java.util.concurrent.ThreadPoolExecutor; import java.util.concurrent.TimeUnit; import java.util.concurrent.atomic.AtomicInteger; import org.slf4j.Logger; import org.slf4j.LoggerFactory; +import org.slf4j.MDC; class StairwayThreadPool extends ThreadPoolExecutor { private static final Logger logger = LoggerFactory.getLogger(StairwayThreadPool.class); AtomicInteger activeTasks; - StairwayThreadPool( - int corePoolSize, - int maximumPoolSize, - long keepAliveTime, - TimeUnit unit, - BlockingQueue workQueue) { - super(corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue); + StairwayThreadPool(int maxParallelFlights) { + super( + maxParallelFlights, + maxParallelFlights, + 0L, + TimeUnit.MILLISECONDS, + new LinkedBlockingQueue<>()); activeTasks = new AtomicInteger(); } @@ -29,10 +33,45 @@ int getQueuedFlights() { return getQueue().size(); } + /** + * Submits a Runnable task for execution and returns a Future representing that task. The Future's + * get method will return null upon successful completion. + * + * @param flightRunner the flight to submit + * @param flightContext + * @return + */ + protected Future submitWithMdcAndFlightContext( + Runnable flightRunner, FlightContext flightContext) { + // Save the calling thread's context before potentially submitting to a child thread + Map callingThreadContext = MDC.getCopyOfContextMap(); + Runnable flightRunnerWithMdc = + () -> { + Map initialContext = MDC.getCopyOfContextMap(); + initializeFlightMdc(callingThreadContext, flightContext); + try { + flightRunner.run(); + } finally { + MdcUtils.overwriteContext(initialContext); + } + }; + return super.submit(flightRunnerWithMdc); + } + + private void initializeFlightMdc( + Map callingThreadContext, FlightContext flightContext) { + // Any leftover context on the thread will be fully overwritten: + MdcUtils.overwriteContext(callingThreadContext); + // If the calling thread's context contains flight and step context from a parent flight, this + // will be overwritten below: + MdcUtils.addFlightContextToMdc(flightContext); + MdcUtils.removeStepContextFromMdc(flightContext); + } + protected void beforeExecute(Thread t, Runnable r) { - super.beforeExecute(t, r); int active = activeTasks.incrementAndGet(); logger.debug("before: " + active); + super.beforeExecute(t, r); } protected void afterExecute(Runnable r, Throwable t) { diff --git a/stairway/src/test/java/bio/terra/stairway/impl/MdcHelperTest.java b/stairway/src/test/java/bio/terra/stairway/impl/MdcUtilsTest.java similarity index 51% rename from stairway/src/test/java/bio/terra/stairway/impl/MdcHelperTest.java rename to stairway/src/test/java/bio/terra/stairway/impl/MdcUtilsTest.java index 4ca9640..e17241e 100644 --- a/stairway/src/test/java/bio/terra/stairway/impl/MdcHelperTest.java +++ b/stairway/src/test/java/bio/terra/stairway/impl/MdcUtilsTest.java @@ -16,22 +16,22 @@ import org.slf4j.MDC; @Tag("unit") -class MdcHelperTest { +class MdcUtilsTest { private static final Map FOO_BAR = Map.of("foo", "bar"); private static final String FLIGHT_ID = "flightId" + UUID.randomUUID(); private static final String FLIGHT_CLASS = "flightClass" + UUID.randomUUID(); private static final Map FLIGHT_MDC = - Map.of(MdcHelper.FLIGHT_ID_KEY, FLIGHT_ID, MdcHelper.FLIGHT_CLASS_KEY, FLIGHT_CLASS); + Map.of(MdcUtils.FLIGHT_ID_KEY, FLIGHT_ID, MdcUtils.FLIGHT_CLASS_KEY, FLIGHT_CLASS); private static final int STEP_INDEX = 2; private static final Direction STEP_DIRECTION = Direction.DO; private static final String STEP_CLASS = "stepClass" + UUID.randomUUID(); private static final Map STEP_MDC = Map.of( - MdcHelper.FLIGHT_STEP_NUMBER_KEY, + MdcUtils.FLIGHT_STEP_NUMBER_KEY, Integer.toString(STEP_INDEX), - MdcHelper.FLIGHT_STEP_DIRECTION_KEY, + MdcUtils.FLIGHT_STEP_DIRECTION_KEY, STEP_DIRECTION.toString(), - MdcHelper.FLIGHT_STEP_CLASS_KEY, + MdcUtils.FLIGHT_STEP_CLASS_KEY, STEP_CLASS); private TestFlightContext flightContext; @@ -54,62 +54,25 @@ static Stream> initialContext() { @ParameterizedTest @MethodSource("initialContext") - void withMdcAndFlightContext(Map initialContext) { - var expectedMdc = new HashMap<>(FLIGHT_MDC); - if (initialContext != null) { - MDC.setContextMap(initialContext); - expectedMdc.putAll(initialContext); - } - - Runnable runnable = - () -> - assertThat( - "Calling thread's context with new flight context", - MDC.getCopyOfContextMap(), - equalTo(expectedMdc)); - MdcHelper.withMdcAndFlightContext(runnable, flightContext).run(); + void overwriteContext(Map initialContext) { + MDC.setContextMap(FOO_BAR); + MdcUtils.overwriteContext(initialContext); + assertThat("", MDC.getCopyOfContextMap(), equalTo(initialContext)); } @ParameterizedTest @MethodSource("initialContext") - void withMdcAndFlightContext_subflight(Map initialContext) { - var expectedParentFlightMdc = new HashMap<>(FLIGHT_MDC); - - var childFlightId = "childFlightId"; - var childFlightClass = "childFlightClass"; - - var childFlightContext = - new TestFlightContext().flightId(childFlightId).flightClassName(childFlightClass); - var expectedChildFlightMdc = new HashMap<>(); - expectedChildFlightMdc.put(MdcHelper.FLIGHT_ID_KEY, childFlightId); - expectedChildFlightMdc.put(MdcHelper.FLIGHT_CLASS_KEY, childFlightClass); - + void addFlightContextToMdc(Map initialContext) { + var expectedMdc = new HashMap<>(); if (initialContext != null) { MDC.setContextMap(initialContext); - expectedParentFlightMdc.putAll(initialContext); - expectedChildFlightMdc.putAll(initialContext); + expectedMdc.putAll(initialContext); } + expectedMdc.putAll(FLIGHT_MDC); - Runnable parentFlight = - () -> { - assertThat( - "Calling thread's context with parent flight context", - MDC.getCopyOfContextMap(), - equalTo(expectedParentFlightMdc)); - // If a child flight is launched within a step in a parent flight, the calling thread's - // context would also contain step-specific context that should be cleared for logs - // emitted by the child flight. - MdcHelper.addStepContextToMdc(flightContext); - Runnable childFlight = - () -> - assertThat( - "Calling thread's context with child flight context", - MDC.getCopyOfContextMap(), - equalTo(expectedChildFlightMdc)); - MdcHelper.withMdcAndFlightContext(childFlight, childFlightContext).run(); - }; - - MdcHelper.withMdcAndFlightContext(parentFlight, flightContext).run(); + MdcUtils.addStepContextToMdc(flightContext); + assertThat( + "Initial context with flight context", MDC.getCopyOfContextMap(), equalTo(expectedMdc)); } @ParameterizedTest @@ -124,13 +87,13 @@ void addAndRemoveStepContextFromMdc(Map initialContext) { } expectedAddStepMdc.putAll(STEP_MDC); - MdcHelper.addStepContextToMdc(flightContext); + MdcUtils.addStepContextToMdc(flightContext); assertThat( "Initial context with new step context", MDC.getCopyOfContextMap(), equalTo(expectedAddStepMdc)); - MdcHelper.removeStepContextFromMdc(flightContext); + MdcUtils.removeStepContextFromMdc(flightContext); assertThat( "Initial context without step context", MDC.getCopyOfContextMap(), diff --git a/stairway/src/test/java/bio/terra/stairway/impl/StairwayThreadPoolTest.java b/stairway/src/test/java/bio/terra/stairway/impl/StairwayThreadPoolTest.java new file mode 100644 index 0000000..5cee939 --- /dev/null +++ b/stairway/src/test/java/bio/terra/stairway/impl/StairwayThreadPoolTest.java @@ -0,0 +1,137 @@ +package bio.terra.stairway.impl; + +import static org.hamcrest.MatcherAssert.assertThat; +import static org.hamcrest.Matchers.equalTo; + +import bio.terra.stairway.fixtures.TestFlightContext; +import java.util.HashMap; +import java.util.Map; +import java.util.UUID; +import java.util.concurrent.ExecutionException; +import java.util.concurrent.TimeUnit; +import java.util.concurrent.TimeoutException; +import java.util.stream.Stream; +import org.junit.jupiter.api.BeforeEach; +import org.junit.jupiter.api.Tag; +import org.junit.jupiter.params.ParameterizedTest; +import org.junit.jupiter.params.provider.MethodSource; +import org.slf4j.MDC; + +@Tag("unit") +class StairwayThreadPoolTest { + + private static final int MAX_PARALLEL_FLIGHTS = 5; + private static final Map FOO_BAR = Map.of("foo", "bar"); + private static final String FLIGHT_ID = "flightId" + UUID.randomUUID(); + private static final String FLIGHT_CLASS = "flightClass" + UUID.randomUUID(); + private static final Map FLIGHT_MDC = + Map.of(MdcUtils.FLIGHT_ID_KEY, FLIGHT_ID, MdcUtils.FLIGHT_CLASS_KEY, FLIGHT_CLASS); + + private StairwayThreadPool stairwayThreadPool; + private TestFlightContext flightContext; + + @BeforeEach + void beforeEach() { + MDC.clear(); + stairwayThreadPool = new StairwayThreadPool(MAX_PARALLEL_FLIGHTS); + flightContext = new TestFlightContext().flightId(FLIGHT_ID).flightClassName(FLIGHT_CLASS); + } + + static Stream> initialContext() { + return Stream.of(null, Map.of(), FOO_BAR); + } + + @ParameterizedTest + @MethodSource("initialContext") + void submitWithMdcAndFlightContext(Map initialContext) + throws ExecutionException, InterruptedException, TimeoutException { + var expectedMdc = new HashMap<>(FLIGHT_MDC); + if (initialContext != null) { + MDC.setContextMap(initialContext); + expectedMdc.putAll(initialContext); + } + + Runnable runnable = + () -> { + assertThat("One active flight", stairwayThreadPool.getActiveFlights(), equalTo(1)); + assertThat( + "Calling thread's context with new flight context", + MDC.getCopyOfContextMap(), + equalTo(expectedMdc)); + }; + + stairwayThreadPool + .submitWithMdcAndFlightContext(runnable, flightContext) + .get(1, TimeUnit.SECONDS); + + assertThat("No more active flights", stairwayThreadPool.getActiveFlights(), equalTo(0)); + assertThat( + "Calling thread's context is unchanged", + MDC.getCopyOfContextMap(), + equalTo(initialContext)); + } + + @ParameterizedTest + @MethodSource("initialContext") + void submitWithMdcAndFlightContext_subflight(Map initialContext) + throws ExecutionException, InterruptedException { + var expectedParentFlightMdc = new HashMap<>(FLIGHT_MDC); + + var childFlightId = "childFlightId"; + var childFlightClass = "childFlightClass"; + + var childFlightContext = + new TestFlightContext().flightId(childFlightId).flightClassName(childFlightClass); + var expectedChildFlightMdc = new HashMap<>(); + expectedChildFlightMdc.put(MdcUtils.FLIGHT_ID_KEY, childFlightId); + expectedChildFlightMdc.put(MdcUtils.FLIGHT_CLASS_KEY, childFlightClass); + + if (initialContext != null) { + MDC.setContextMap(initialContext); + expectedParentFlightMdc.putAll(initialContext); + expectedChildFlightMdc.putAll(initialContext); + } + + Runnable childFlight = + () -> { + assertThat( + "Two active flights (parent and child)", + stairwayThreadPool.getActiveFlights(), + equalTo(2)); + assertThat( + "Calling thread's context with child flight context", + MDC.getCopyOfContextMap(), + equalTo(expectedChildFlightMdc)); + }; + Runnable parentFlight = + () -> { + assertThat( + "One active flight (parent)", stairwayThreadPool.getActiveFlights(), equalTo(1)); + assertThat( + "Calling thread's context with parent flight context", + MDC.getCopyOfContextMap(), + equalTo(expectedParentFlightMdc)); + // If a child flight is launched within a step in a parent flight, the calling thread's + // context would also contain step-specific context that should be cleared for logs + // emitted by the child flight. + MdcUtils.addStepContextToMdc(flightContext); + try { + stairwayThreadPool + .submitWithMdcAndFlightContext(childFlight, childFlightContext) + .get(1, TimeUnit.SECONDS); + } catch (Exception e) { + System.out.println("Exception " + e); + throw new RuntimeException(e); + } + assertThat( + "One active flight (parent)", stairwayThreadPool.getActiveFlights(), equalTo(1)); + }; + stairwayThreadPool.submitWithMdcAndFlightContext(parentFlight, flightContext).get(); + + assertThat("No more active flights", stairwayThreadPool.getActiveFlights(), equalTo(0)); + assertThat( + "Calling thread's context is unchanged", + MDC.getCopyOfContextMap(), + equalTo(initialContext)); + } +} From b47d695584b212e8ab8ae0a5dcd4c789b6e5ce44 Mon Sep 17 00:00:00 2001 From: Olivia Kotsopoulos Date: Fri, 1 Mar 2024 17:29:43 -0500 Subject: [PATCH 07/10] Fix MdcUtilsTest.addFlightContextToMdc --- .../src/test/java/bio/terra/stairway/impl/MdcUtilsTest.java | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/stairway/src/test/java/bio/terra/stairway/impl/MdcUtilsTest.java b/stairway/src/test/java/bio/terra/stairway/impl/MdcUtilsTest.java index e17241e..9b21dbd 100644 --- a/stairway/src/test/java/bio/terra/stairway/impl/MdcUtilsTest.java +++ b/stairway/src/test/java/bio/terra/stairway/impl/MdcUtilsTest.java @@ -70,7 +70,7 @@ void addFlightContextToMdc(Map initialContext) { } expectedMdc.putAll(FLIGHT_MDC); - MdcUtils.addStepContextToMdc(flightContext); + MdcUtils.addFlightContextToMdc(flightContext); assertThat( "Initial context with flight context", MDC.getCopyOfContextMap(), equalTo(expectedMdc)); } From 7d4c7921055f221ec8b1c7e2b0fc836e416387ca Mon Sep 17 00:00:00 2001 From: Olivia Kotsopoulos Date: Fri, 1 Mar 2024 17:33:05 -0500 Subject: [PATCH 08/10] Enable Gradle scans on unit test runs --- .github/workflows/build-and-test.yaml | 2 +- buildSrc/src/main/groovy/stairway.java-conventions.gradle | 8 ++++++++ 2 files changed, 9 insertions(+), 1 deletion(-) diff --git a/.github/workflows/build-and-test.yaml b/.github/workflows/build-and-test.yaml index bba207b..9dae747 100644 --- a/.github/workflows/build-and-test.yaml +++ b/.github/workflows/build-and-test.yaml @@ -47,7 +47,7 @@ jobs: distribution: 'temurin' cache: 'gradle' - name: Run tests - run: ./gradlew test + run: ./gradlew test --scan # TODO: Work with AppSec to get Sonar scans setup for this repo # Run the Sonar scan after `gradle test` to include code coverage data in its report. diff --git a/buildSrc/src/main/groovy/stairway.java-conventions.gradle b/buildSrc/src/main/groovy/stairway.java-conventions.gradle index 6c9e6f2..d7c5eb7 100644 --- a/buildSrc/src/main/groovy/stairway.java-conventions.gradle +++ b/buildSrc/src/main/groovy/stairway.java-conventions.gradle @@ -43,3 +43,11 @@ test { includeTags 'unit' } } + +// for scans +if (hasProperty("buildScan")) { + buildScan { + termsOfServiceUrl = "https://gradle.com/terms-of-service" + termsOfServiceAgree = "yes" + } +} From 981703e5a28be522aa45311c60428dbaf52bf2c0 Mon Sep 17 00:00:00 2001 From: Olivia Kotsopoulos Date: Fri, 1 Mar 2024 17:53:05 -0500 Subject: [PATCH 09/10] Stabilize StairwayThreadPoolTests, flaky in CI Removed checks on stairwayThreadPool.getActiveFlights, which is only used in debug logging. --- .../stairway/impl/StairwayThreadPoolTest.java | 37 ++++++------------- 1 file changed, 12 insertions(+), 25 deletions(-) diff --git a/stairway/src/test/java/bio/terra/stairway/impl/StairwayThreadPoolTest.java b/stairway/src/test/java/bio/terra/stairway/impl/StairwayThreadPoolTest.java index 5cee939..e68abe3 100644 --- a/stairway/src/test/java/bio/terra/stairway/impl/StairwayThreadPoolTest.java +++ b/stairway/src/test/java/bio/terra/stairway/impl/StairwayThreadPoolTest.java @@ -2,6 +2,7 @@ import static org.hamcrest.MatcherAssert.assertThat; import static org.hamcrest.Matchers.equalTo; +import static org.junit.jupiter.api.Assertions.fail; import bio.terra.stairway.fixtures.TestFlightContext; import java.util.HashMap; @@ -52,19 +53,16 @@ void submitWithMdcAndFlightContext(Map initialContext) } Runnable runnable = - () -> { - assertThat("One active flight", stairwayThreadPool.getActiveFlights(), equalTo(1)); - assertThat( - "Calling thread's context with new flight context", - MDC.getCopyOfContextMap(), - equalTo(expectedMdc)); - }; + () -> + assertThat( + "Calling thread's context with new flight context", + MDC.getCopyOfContextMap(), + equalTo(expectedMdc)); stairwayThreadPool .submitWithMdcAndFlightContext(runnable, flightContext) .get(1, TimeUnit.SECONDS); - assertThat("No more active flights", stairwayThreadPool.getActiveFlights(), equalTo(0)); assertThat( "Calling thread's context is unchanged", MDC.getCopyOfContextMap(), @@ -93,20 +91,13 @@ void submitWithMdcAndFlightContext_subflight(Map initialContext) } Runnable childFlight = - () -> { - assertThat( - "Two active flights (parent and child)", - stairwayThreadPool.getActiveFlights(), - equalTo(2)); - assertThat( - "Calling thread's context with child flight context", - MDC.getCopyOfContextMap(), - equalTo(expectedChildFlightMdc)); - }; + () -> + assertThat( + "Calling thread's context with child flight context", + MDC.getCopyOfContextMap(), + equalTo(expectedChildFlightMdc)); Runnable parentFlight = () -> { - assertThat( - "One active flight (parent)", stairwayThreadPool.getActiveFlights(), equalTo(1)); assertThat( "Calling thread's context with parent flight context", MDC.getCopyOfContextMap(), @@ -120,15 +111,11 @@ void submitWithMdcAndFlightContext_subflight(Map initialContext) .submitWithMdcAndFlightContext(childFlight, childFlightContext) .get(1, TimeUnit.SECONDS); } catch (Exception e) { - System.out.println("Exception " + e); - throw new RuntimeException(e); + fail("Unexpected exception waiting for child flight", e); } - assertThat( - "One active flight (parent)", stairwayThreadPool.getActiveFlights(), equalTo(1)); }; stairwayThreadPool.submitWithMdcAndFlightContext(parentFlight, flightContext).get(); - assertThat("No more active flights", stairwayThreadPool.getActiveFlights(), equalTo(0)); assertThat( "Calling thread's context is unchanged", MDC.getCopyOfContextMap(), From b669bb853e03f420dc1fd4c95f2899a02ca1066b Mon Sep 17 00:00:00 2001 From: Olivia Kotsopoulos Date: Mon, 4 Mar 2024 11:28:27 -0500 Subject: [PATCH 10/10] PR feedback: rewrite MdcUtils.overwriteContext for clarity And revisiting MdcUtilsTest with some naming changes for clarity. --- .../java/bio/terra/stairway/impl/MdcUtils.java | 5 ++--- .../java/bio/terra/stairway/impl/MdcUtilsTest.java | 14 +++++++------- 2 files changed, 9 insertions(+), 10 deletions(-) diff --git a/stairway/src/main/java/bio/terra/stairway/impl/MdcUtils.java b/stairway/src/main/java/bio/terra/stairway/impl/MdcUtils.java index 0bd0833..5d8e01b 100644 --- a/stairway/src/main/java/bio/terra/stairway/impl/MdcUtils.java +++ b/stairway/src/main/java/bio/terra/stairway/impl/MdcUtils.java @@ -31,9 +31,8 @@ class MdcUtils { * @param context to set as MDC, if null then MDC will be cleared. */ static void overwriteContext(Map context) { - if (context == null) { - MDC.clear(); - } else { + MDC.clear(); + if (context != null) { MDC.setContextMap(context); } } diff --git a/stairway/src/test/java/bio/terra/stairway/impl/MdcUtilsTest.java b/stairway/src/test/java/bio/terra/stairway/impl/MdcUtilsTest.java index 9b21dbd..be36c15 100644 --- a/stairway/src/test/java/bio/terra/stairway/impl/MdcUtilsTest.java +++ b/stairway/src/test/java/bio/terra/stairway/impl/MdcUtilsTest.java @@ -48,20 +48,20 @@ void beforeEach() { .stepClassName(STEP_CLASS); } - static Stream> initialContext() { + static Stream> contextMap() { return Stream.of(null, Map.of(), FOO_BAR); } @ParameterizedTest - @MethodSource("initialContext") - void overwriteContext(Map initialContext) { + @MethodSource("contextMap") + void overwriteContext(Map newContext) { MDC.setContextMap(FOO_BAR); - MdcUtils.overwriteContext(initialContext); - assertThat("", MDC.getCopyOfContextMap(), equalTo(initialContext)); + MdcUtils.overwriteContext(newContext); + assertThat("MDC overwritten by new context", MDC.getCopyOfContextMap(), equalTo(newContext)); } @ParameterizedTest - @MethodSource("initialContext") + @MethodSource("contextMap") void addFlightContextToMdc(Map initialContext) { var expectedMdc = new HashMap<>(); if (initialContext != null) { @@ -76,7 +76,7 @@ void addFlightContextToMdc(Map initialContext) { } @ParameterizedTest - @MethodSource("initialContext") + @MethodSource("contextMap") void addAndRemoveStepContextFromMdc(Map initialContext) { var expectedAddStepMdc = new HashMap<>(); var expectedRemoveStepMdc = new HashMap<>();