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]

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

[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.

[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: https://github.com/akka/akka-http/pull/3974#discussion_r875025973

[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 https://github.com/akka/akka-http/pull/3974/commits/17c654019ce0bff974e724b78b820435314dc4d2

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