MdcLoggingDirectives (withMdcLogging, withMdcEntry, withMdcEntries, extractMarkerLog)

[alexklibisz]

This is a first pass at four new directives to simplify MDC logging.

It didn't require any internal changes, rather just a matter of using existing APIs to expose a more convenient API for attaching MDC entries to a request's logger.

My team has used this in production for a few months, so we figured it would be nice to contribute back.

I'm happy to iterate on the API and implementation as needed. Some notes:

1. For documentation, I just mimicked some of the existing directive docs. I was able to get them rendered locally w/ paradox.
2. I left out the Java implementation and examples for now. Once we are happy with the API, I can go back and do the Java implementation and examples.

Related to #3378

[alexklibisz]

LL 27 to 35 were purely type tetris on my part. They work, but I'm not 100% sure I setup the logger the right way. Very open to input here.

[alexklibisz]

Hi @jrudolph, just pinging to see if you or the other akka folks have had a chance to look this over. Thanks.

[jrudolph]

Thanks for the contribution (and sorry for the delay).

I think the idea is nice to have directives to add MDC values.

I see two issues with the implementation:

• DiagnosticMarkerBusLoggingAdapter is not thread-safe so the directive will probably overwrite MDCs randomly when requests are handled concurrently but the log is shared. On one hand, in most cases, extractDiagnosticMarkerLog will probably recreate a new log, so hopefully that one wouldn't be shared (however, you cannot be sure ctx.log could be a shared LoggingAdapter). On the other hand, even the recreated one is not safe to be used in a route because routes can executed concurrently and there may be race conditions and visibility issues even with the dedicated log.
• the directives don't ensure that MDC values are removed when a request is not handled by an inner route, so the values would still apply even if the request is handled by a sibling route.

To me it seems that Akka's DiagnosticLoggingAdapter is not up for the job here. In the best case, we would need an immutable variant of DiagnosticLoggingAdapter that can safely be shared. Ultimately, this would be nice to have in Akka itself but we can start with building it here if you like.

[alexklibisz]

Thanks for the thorough review @jrudolph.

To your notes on thread-safety: I had assumed that once a request is "inside" of a directive, akka-http will evaluate everything serially. Sure, you can kick off your own Futures, etc., and those could concurrently access the logging adapter. But akka-http will execute nested directives serially for a single request. It seems like that might be an incorrect assumption?

If you happen to know of any examples floating around that demonstrate concurrency issues, that would be very helpful.
We have a nearly identical version of these directives deployed internally, along with some more aggressive tests for parallel invocations, and we haven't noticed any concurrency-related confusion (though it could be elusive).

I'll have to do some more research on how it would look to add an immutable DiagnosticLoggingAdapter, either here or in akka. I'm definitely interested in getting this correct, even if it takes a bit longer -- no major rush on my end.

[alexklibisz]

I pushed up a couple small suggested changes.

I want to make sure I understand the thread-safety concerns here. It sounds like we're specifically concerned about a case like this:

1. Instantiate a singleton DiagnosticMarkerBusLoggingAdapter.
2. Use an existing directive like mapRequestContext to provide that singleton as the log for every request.
3. Since log is already a DiagnosticMarkerBusLoggingAdapter, any routes that use extractDiagnosticMarkerLog will not create a new instance of DiagnosticMarkerBusLoggingAdapter.
4. Any routes that use withMdcEntries, if called concurrently, will concurrently update the MDC map inside of the singleton. This is the race condition.

Right now I can't think of any other way to induce a race condition here.

And while the scenario above seems possible, it also seems like it is already entirely possible (and also a bad idea) to instantiate a singleton DiagnosticMarkerBusLoggingAdapter and share it among requests. The docs for DiagnosticMarkerBusLoggingAdapter already indicate it's not thread-safe. The new directives don't make it any easier to make this mistake.

If my premises above are valid, maybe a simple solution here would be to just create a new DiagnosticMarkerBusLoggingAdapter on every call to extractDiagnosticMarkerLog? Something like this:

private val extractDiagnosticMarkerLog: Directive1[DiagnosticMarkerBusLoggingAdapter] =
    extractActorSystem
      .flatMap { sys =>
        extractRequestContext
          .flatMap { ctx =>
            provide {
              ctx.log match {
                // If it's already a DiagnosticMarkerBusLoggingAdapter, create a new one, copying the old MDC.
                case oldDmbla: DiagnosticMarkerBusLoggingAdapter =>
                  import oldDmbla._
                  val newDmbla = new DiagnosticMarkerBusLoggingAdapter(bus, logSource, logClass, loggingFilterWithMarker)
                  newDmbla.mdc(oldDmbla.mdc)
                  newDmbla
                // Otherwise, we need to construct a DiagnosticLoggingAdapter.
                case _ =>
                  val (str, cls) = LogSource.fromAnyRef(sys, sys)
                  val filter = new DefaultLoggingFilter(sys.settings, sys.eventStream)
                  new DiagnosticMarkerBusLoggingAdapter(sys.eventStream, str, cls, filter)
              }
            }
          }
      }

[jrudolph]

If my premises above are valid, maybe a simple solution here would be to just create a new DiagnosticMarkerBusLoggingAdapter on every call to extractDiagnosticMarkerLog? Something like this:

I think that would be a good idea. I'd say it would be acceptable to use DiagnosticMarkerBusLoggingAdapter when it is never explicitly exposed and no one is likely to modify the MDC settings after creation.

Without that change something like

    withMdcEntry("user_id", "1234") {
      extractLog { log =>
           val fut = loadFromDB(log) // log used asynchronously here and may include mdc entries only defined below

           withMdcEntry("request_id", "abcd") {
              // and here again
              log.info("completing request")
              complete(StatusCodes.OK)
          }
        }
      }
    }

might go wrong.

[jrudolph]

Do we need that, aren't all logger also MarkerLoggingAdapters anyway even without withMdcLogging enabled?

[alexklibisz]

aren't all logger also MarkerLoggingAdapters anyway even without withMdcLogging enabled?

I don't think so. I'm assuming you're implying we could just use extractLog instead of having this.

extractLog returns a LoggingAdapter:

akka-http/akka-http/src/main/scala/akka/http/scaladsl/server/directives/BasicDirectives.scala

Line 279 in 90b5ecb

def extractLog: Directive1[LoggingAdapter] =

MarkerLoggingAdapter has a few extra methods, e.g., https://github.com/akka/akka/blob/main/akka-actor/src/main/scala/akka/event/Logging.scala#L1848-L1849

Maybe it's true that the LoggingAdapter that gets returned from extractLog happens to always also extend MarkerLoggingAdapter, but that's not specified in the return type, so we can't access those methods.

[alexklibisz]

Thanks for the feedback @jrudolph . I'll pick back up on this in the next few days for another pass.

[alexklibisz]

Hi @jrudolph , let me know if you have any thoughts on the latest state of this.

[johanandren]

Sorry for the silence here, @alexklibisz , would you be interested in completing this work with the new license?

[alexklibisz]

Sorry for the silence here, @alexklibisz , would you be interested in completing this work with the new license?

I'm not really sure how contribution has changed since the license change. I've been putting off this PR primarily due to that potential complexity. I won't be offended if you close the PR. I also won't be offended if someone else takes over this PR.

[johanandren]

The only difference is that it would end up being released under the new (source available) BSL rather than the previous (open source) Apache License.

[lightbend-cla-validator]

Hi @alexklibisz,

Thank you for your contribution! We really value the time you've taken to put this together.

We see that you have signed the Lightbend Contributors License Agreement before, however, the CLA has changed since you last signed it.
Please review the new CLA and sign it before we proceed with reviewing this pull request:

https://www.lightbend.com/contribute/cla

[alexklibisz]

I merged in main and applied the suggestion from this thread: #3974 (comment)

[alexklibisz]

I am pretty confused by the CLA. What exactly changed since the last CLA? Obviously the overall project license changed. But is there a diff of the two CLAs somewhere so I can see what I'm re-agreeing to?

[johanandren]

Very late retply, sorry: I think the CLA does not differ, AFAICS it does not mention the license, you still keep your copyright etc., that the CLA checker requires re-sign is more of a technical inconvenience with our CLA checker/database.

[lightbend-cla-validator]

Hi @alexklibisz,

Thank you for your contribution! We really value the time you've taken to put this together.

We see that you have signed the Lightbend Contributors License Agreement before, however, the CLA has changed since you last signed it.
Please review the new CLA and sign it before we proceed with reviewing this pull request:

https://www.lightbend.com/contribute/cla

[alexklibisz]

Hi @alexklibisz,

Thank you for your contribution! We really value the time you've taken to put this together.

We see that you have signed the Lightbend Contributors License Agreement before, however, the CLA has changed since you last signed it. Please review the new CLA and sign it before we proceed with reviewing this pull request:

https://www.lightbend.com/contribute/cla

Still need to clarify something regarding the CLA.

[alexklibisz]

Tests should be passing on 2.12 and 2.13 now. Still need to clarify something regarding the CLA.

[alexklibisz]

FYI, I'm seeing a peculiar issue when testing locally: when I run MdcLoggingDirectivesSpec from the sbt repl, it fails on the first run and then reliably passes. When I run via sbt command (no repl), it reliably fails. Always the last test case "include the entries in the LoggingEvents":

[info] - should include the entries in the LoggingEvents *** FAILED *** (25 milliseconds)
[info]   0 was not equal to 3 (MdcLoggingDirectivesSpec.scala:79)

Seems like something related to the JVM just having booted? Strange

Edit: should be fixed in 17c6540

As an aside, it would be nice to be able to get Events out of an EventFilter. I've run into this a few times.

[lightbend-cla-validator]

Hi @alexklibisz,

Thank you for your contribution! We really value the time you've taken to put this together.

We see that you have signed the Lightbend Contributors License Agreement before, however, the CLA has changed since you last signed it.
Please review the new CLA and sign it before we proceed with reviewing this pull request:

https://www.lightbend.com/contribute/cla

[johanandren]

I'd recommend nesting 3 EventFilter.custom instead of the volatile field scheme, looking at the mdc values in the filters instead of after the fact. First log event will go innermost. I think it can match on exact log message and fail explicitly with a scalatest fail if the mdc isn't what it should be to provide extra detail.