[WOR-1544] #major Populate MDC for flight and its steps #125

okotsopoulos · 2024-02-29T17:27:00Z

https://broadworkbench.atlassian.net/browse/WOR-1544

Centralizing work done in DataBiosphere/terra-workspace-manager#1626, 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.

In Action

I published my Stairway branch locally, pulled it in as a WSM dependency, removed the existing WSM code which modifies the MDC, deployed it to my Bee, and hit an endpoint that triggers a stairway flight.

The resulting logs have their MDC populated as described in this PR: https://cloudlogging.app.goo.gl/T9vdJ86RXRoa117VA

Calling thread's context over the entirety of the flight (that's where jsonPayload.requestId comes from)
Flight-specific context over the entirety of the flight
Step-specific context over the entirety of each step

A jsonPayload for a log emitted during a step:

All of the logs for the request, with flightId, flightStepNumber, and flightStepDirection added to the summary line:

(As an aside, it's clear to me that these log lines can be substantially trimmed. Do we need the full formatted summary anymore if we have this info in the MDC, and can pull it in the summary line?)

How can my service get this new functionality?

Once this PR is merged, I'll update the dependency in TCL, which is where most services get Stairway from. At any rate, downstream services will need to update a dependency.

If downstream services presently modify their MDCs themselves, they will be able to remove that code in their service and let Stairway take care of it.

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.

In a follow-on PR, will automate spotlessCheck to gate PRs.

okotsopoulos · 2024-02-29T22:35:23Z

stairway/src/main/java/bio/terra/stairway/impl/FlightRunner.java

-          flightContext.getFlightClassName(),
-          flightContext.getStepIndex(),
-          flightContext.getStepClassName());
+          "{} (index {}) experienced DISMAL FAILURE: non-retryable error on undo",


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.

I also reformatted to lead with the failing step class based off of Stairway retro feedback that all of the useful information on a log line is at the end. Do we like this better? Unfortunately we don't get step context in MDC for free at this point -- we're outside of step execution.

And some other formatting and documentation changes.

The MdcHelper methods are only meant to be called within the Stairway implementation package.

okotsopoulos · 2024-03-01T00:52:08Z

README.md

+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


Propagating the MDC from the calling thread makes me want to designate this as a minor version bump at minimum. Default behavior in this repo is patch bumps.

Reviewers, WDYT?

I agree with a more significant version bump. Though with all the dependency upgrades underway, I was already thinking we would do a major version bump very soon. Perhaps just do a major bump with this change?

Good idea. I'll make it a major one.

Added #major to the PR title, which will get pulled into the commit message.

okotsopoulos · 2024-03-01T00:52:46Z

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'


Needed this expanded dependency for parameterized tests, and upgraded while in the neighborhood.

cahrens · 2024-03-01T14:05:19Z

stairway/src/main/java/bio/terra/stairway/impl/MdcHelper.java

+    Map<String, String> contextMap = MDC.getCopyOfContextMap();
+    return () -> {
+      // Any leftover context on the thread will be fully overwritten:
+      MDC.setContextMap(Optional.ofNullable(contextMap).orElse(Map.of()));


I'm having trouble understanding this line. We are getting a copy of the context map at line 35, so why isn't line 38 effectively a no-op?

Ah, great question. Stairway spawns new threads for flight execution, so this Runnable within may be happening on a new thread without the prior context.

But this tells me that this code would be better organized if it's added to the Stairway thread pool implementation instead. I'll make that change.

Hi @cahrens , I reorganized this code to live in StairwayThreadPool and feel like it makes more sense now, thanks for the original comment. Would you mind taking another look?

stairway/src/main/java/bio/terra/stairway/impl/MdcHelper.java

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.

okotsopoulos · 2024-03-01T21:33:06Z

stairway/src/main/java/bio/terra/stairway/impl/StairwayThreadPool.java

    int active = activeTasks.incrementAndGet();
    logger.debug("before: " + active);
+    super.beforeExecute(t, r);


Reading the docstring on this method, it's recommended to call the super at the end to allow for potential nesting.

(I also read the docstring on afterExecute, and the super call at the beginning matches the recommendation.)

Removed checks on stairwayThreadPool.getActiveFlights, which is only used in debug logging.

cahrens · 2024-03-04T15:19:04Z

.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


What does this do?

This generates a Gradle build scan as part of test output, which makes debugging tests a lot easier. Example from the most recent unit test run:

Publishing build scan... https://gradle.com/s/gu4jckjm4mqzq

stairway/src/main/java/bio/terra/stairway/impl/MdcUtils.java

And revisiting MdcUtilsTest with some naming changes for clarity.

sonarcloud · 2024-03-04T16:38:41Z

Quality Gate passed

Issues
2 New issues
0 Accepted issues

Measures
0 Security Hotspots
0.0% Coverage on New Code
0.0% Duplication on New Code

See analysis details on SonarCloud

okotsopoulos added 2 commits February 29, 2024 12:22

Cannot call MDC.setContextMap with a null input

15f1718

okotsopoulos changed the title ~~Okotsopo wor 1544 mdc~~ [WOR-1544] Populate MDC for flight and its steps Feb 29, 2024

Add unit tests, spotlessApply

0967119

In a follow-on PR, will automate spotlessCheck to gate PRs.

okotsopoulos commented Feb 29, 2024

View reviewed changes

okotsopoulos added 2 commits February 29, 2024 17:42

Update README to highlight MDC additions

6668262

And some other formatting and documentation changes.

MdcHelper, MdcHelperTest needn't be public

4ac56fa

The MdcHelper methods are only meant to be called within the Stairway implementation package.

okotsopoulos commented Mar 1, 2024

View reviewed changes

okotsopoulos marked this pull request as ready for review March 1, 2024 00:52

okotsopoulos commented Mar 1, 2024

View reviewed changes

cahrens reviewed Mar 1, 2024

View reviewed changes

stairway/src/main/java/bio/terra/stairway/impl/MdcHelper.java Outdated Show resolved Hide resolved

dvoet approved these changes Mar 1, 2024

View reviewed changes

okotsopoulos changed the title ~~[WOR-1544] Populate MDC for flight and its steps~~ [WOR-1544] #major Populate MDC for flight and its steps Mar 1, 2024

okotsopoulos requested a review from cahrens March 1, 2024 21:31

okotsopoulos commented Mar 1, 2024

View reviewed changes

okotsopoulos marked this pull request as draft March 1, 2024 21:43

okotsopoulos added 3 commits March 1, 2024 17:29

Fix MdcUtilsTest.addFlightContextToMdc

b47d695

Enable Gradle scans on unit test runs

7d4c792

Stabilize StairwayThreadPoolTests, flaky in CI

981703e

Removed checks on stairwayThreadPool.getActiveFlights, which is only used in debug logging.

okotsopoulos marked this pull request as ready for review March 1, 2024 23:06

cahrens reviewed Mar 4, 2024

View reviewed changes

stairway/src/main/java/bio/terra/stairway/impl/MdcUtils.java Show resolved Hide resolved

cahrens approved these changes Mar 4, 2024

View reviewed changes

PR feedback: rewrite MdcUtils.overwriteContext for clarity

b669bb8

And revisiting MdcUtilsTest with some naming changes for clarity.

okotsopoulos merged commit 11626a4 into develop Mar 4, 2024
3 checks passed

okotsopoulos deleted the okotsopo-WOR-1544-mdc branch March 4, 2024 16:44

okotsopoulos mentioned this pull request Mar 4, 2024

[WOR-1544] Upgrade Stairway to 1.0.0 for context-awareness DataBiosphere/terra-common-lib#163

Merged

okotsopoulos mentioned this pull request Mar 18, 2024

[WOR-1560] WSM uses Stairway 1.0.0's native MDC support DataBiosphere/terra-workspace-manager#1666

Merged

mmorgantaylor mentioned this pull request Mar 19, 2024

TSPS-188 Remove MdcHook in favor of StairwayLoggingHook DataBiosphere/terra-scientific-pipelines-service#67

Merged

This was referenced Mar 22, 2024

[WOR-1560] Upgrade to TCL 1.0.10 for MDC-aware Stairway DataBiosphere/terra-landing-zone-service#424

Merged

[WOR-1560] Upgrade to TCL 1.1.1 for MDC-aware Stairway DataBiosphere/terra-billing-profile-manager#418

Merged

okotsopoulos mentioned this pull request Apr 3, 2024

[DCST-4] Spring Boot 3.2.4, TCL 1.1.10 DataBiosphere/jade-data-repo#1635

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[WOR-1544] #major Populate MDC for flight and its steps #125

[WOR-1544] #major Populate MDC for flight and its steps #125

okotsopoulos commented Feb 29, 2024 •

edited

Loading

okotsopoulos Feb 29, 2024

okotsopoulos Mar 1, 2024

cahrens Mar 1, 2024

okotsopoulos Mar 1, 2024

okotsopoulos Mar 1, 2024

okotsopoulos Mar 1, 2024

cahrens Mar 1, 2024

okotsopoulos Mar 1, 2024

okotsopoulos Mar 1, 2024

okotsopoulos Mar 1, 2024

cahrens Mar 4, 2024

okotsopoulos Mar 4, 2024

sonarcloud bot commented Mar 4, 2024

[WOR-1544] #major Populate MDC for flight and its steps #125

[WOR-1544] #major Populate MDC for flight and its steps #125

Conversation

okotsopoulos commented Feb 29, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

sonarcloud bot commented Mar 4, 2024

Quality Gate passed

okotsopoulos commented Feb 29, 2024 •

edited

Loading