Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

MdcLoggingDirectives (withMdcLogging, withMdcEntry, withMdcEntries, extractMarkerLog) #3974

Open
wants to merge 10 commits into
base: main
Choose a base branch
from

Conversation

alexklibisz
Copy link

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

.gitignore Outdated Show resolved Hide resolved
.gitignore Outdated Show resolved Hide resolved
case _: DiagnosticMarkerBusLoggingAdapter => ctx
// Otherwise, we need to give the context a DiagnosticLoggingAdapter.
case _ =>
val (str, cls) = LogSource.fromAnyRef(sys, sys)
Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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
Copy link
Author

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

Copy link
Member

@jrudolph jrudolph left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

.gitignore Outdated Show resolved Hide resolved
.gitignore Outdated Show resolved Hide resolved
@alexklibisz
Copy link
Author

alexklibisz commented Feb 10, 2022

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
Copy link
Author

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
Copy link
Member

jrudolph commented Apr 4, 2022

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.

}
}

def extractMarkerLog: Directive1[MarkerLoggingAdapter] =
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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:

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
Copy link
Author

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

- All MDC directives create a new MarkerLoggingAdapter to avoid race conditions.
- Combined withMdcLogging and extractMarkerLog into a single directive withMarkerLoggingAdapter.
- Updated tests to account for the expectation that ever call to a directive creates a new logging adapter.
- Added a test using the EventFilter to verify that the entries are actually being attached.
@alexklibisz alexklibisz requested a review from jrudolph May 14, 2022 18:53
@alexklibisz
Copy link
Author

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

@johanandren
Copy link
Member

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

@alexklibisz
Copy link
Author

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
Copy link
Member

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.

…erBusLoggingAdapter

- Based on suggestion here: https://github.com/akka/akka-http/pull/3974/files/776f4ef37bec392a9afa96ccd10a9b1d64660c9b#r875025973
- This is not yet adequately tested.
- Had to slightly tweak a test because behavior of EventFilter seems to have changed.
@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
Copy link
Author

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

@alexklibisz
Copy link
Author

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
Copy link
Member

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
Copy link
Author

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
Copy link
Author

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

@alexklibisz
Copy link
Author

alexklibisz commented May 30, 2023

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

case _ => false
}
}
val filter = new EF(3)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

5 participants