Provide a way to perform additional work in `Logging{Client,Service}`

[trustin]

For example, a user may have some MDC property he or she wants to be logged. To make the current MDC property is transferred to the moment where Logging{Client,Service} logs something, a user has to:

1. Store the current thread's MDC property somewhere, e.g. local variable.
2. When Logging{Client,Service} logs something, load the property from (1) and set it to an MDC property.
3. After logging is done, the MDC property set in (2) has to be cleared or reverted to the old value.

To make this possible, we need to allow a user specify some custom logic which is executed when:

• Logging{Client.execute,Service.serve}() is called, for the step 1.
• Before and after logging, for the step 2 and 3.

I'm not really sure if you need to allow running an arbitrary logic, though. It may be just enough to let a user specify a list of MDC keys, so they are stored and loaded automatically. Thoughts?

[trustin]

/cc @okue

[okue]

It would be nice if I could write

try (SafeCloseable ignored = Clients.withMDC("key", value)) {
    client.execute(req)
}

[ikhoon]

I think we can take an idea from the MDCContext style used in Kotlin coroutine. https://github.com/Kotlin/kotlinx.coroutines/blob/d7de5f5ba66a8d005e5cbd03b18522112303fd54/integration/kotlinx-coroutines-slf4j/src/MDCContext.kt#L24-L28

MDC.put("kotlin", "rocks") // Put a value into the MDC context
// Capture current MDC context to some storage such as ContextStorage
try (SafeCloseable ignored = Clients.withMDCContext()) {
    logger.info("...")
}

[ikhoon]

https://twitter.github.io/finatra/user-guide/logging/mdc.html Finatra supports MDC by LoggingMDCFilter.

That replaces the standard MDCAdapter with a custom adapter.

def init(): Unit = {
  MDC.getMDCAdapter // Make sure default MDC static initializer has run
  MDC.mdcAdapter = new FinagleMDCAdapter // Swap in the Finagle adapter
}

https://github.com/twitter/finatra/blob/16ca2610222e0da97d14a051dd4aa793f9b7320a/inject/inject-slf4j/src/main/scala/org/slf4j/FinagleMDCInitializer.scala#L17-L27

[trustin]

Here's a new proposal for this issue:

• Add RequestContext.mdc() which provides a request-scoped properties. The API will be pretty much same with org.slf4j.MDC except that the methods are not static:

  ctx.mdc().put("key", "value");

• To expose the request-scoped properties to logging frameworks, use the trick from Finatra, as mentioned in https://github.com/line/armeria/issues/2634#issuecomment-620411977
  • When there's a thread-local RequestContext, request-scoped properties are retrieved. If there's no thread-local RequestContext or a certain property is not found, thread-scoped MDC properties are retrieved instead.
  • However, MDC.put() will not set request-scoped MDC property even if a thread-local RequestContext is set, i.e. a request-scoped property must be set via ctx.mdc().put(). This is to avoid the ambiguity of lifecycle between request- and thread- scoped properties.
• For the client-side, a user can set a request-scoped property using Clients.withContextCustomizer():

  try (SafeCloseable ignored = Clients.withContextCustomizer(ctx -> {
    ctx.mdc().put("key", "value");
    // or for mass import:
    ctx.mdc().importThreadLocalMdc();
  }) {
    client.get("/");
  }

Let me know what you think! /cc @okue @anuraaga

[anuraaga]

Since we already have "request-scoped properties" in the context itself, it seems a little weird to have yet another map of properties. Didn't we already have a mechanism for attributes to be marked as log exported? Might be misremembering or misunderstanding this issue.

[trustin]

IIRC, @okue has a Logback message pattern which refers to a certain MDC property (transaction ID), but it was lost when LoggingClient/Service writes a log message.

At second thought, we can now specify a custom name for a RequestContext attribute, which was not possible previously, so a user can just do this:

static final AttributeKey TRANSACTION_ID = ...;

try (SafeCloseable ignored = Clients.withContextCustomizer(ctx -> {
    ctx.setAttr(TRANSACTION_ID, "...");
}) {
    client.get("/");
}

in logback.xml:

  <appender name="RCEA" class="com.linecorp.armeria.common.logback.RequestContextExportingAppender">
    <appender-ref ref="CONSOLE" />
    <export>txid=attr:com.example.AttrKeys#TRANSACTION_ID</exports>
  </appender>

That is, we can probably scratch my proposal. :sweat_smile: Would this work for you, @okue ?

[okue]

https://github.com/line/armeria/issues/2634#issuecomment-625644364 is not preferable for the case that many values may be set to MDC.

In this case, users have to write many <export>...</export> tags corresponding to MDC values in logback.xml. This may cause us to forget to write a necessary <export> tag, then some values are not exported to MDC.

(Actually, my app is setting more than 20 values to MDC.)

[trustin]

Here's @okue's workaround (or maybe the right solution?) that uses RequestContextStorage:

https://gist.github.com/okue/cab0d3f48d87def319bb66f6254e4dea

(from his Slack message at #general)

[anuraaga]

Is the only problem the maintenance of the export? Perhaps we can allow wildcard for custom keys too using some simple mapping

<export>mylogs.*=attr:com.example.LogKeys#*

[minwoox]

Well, customizing the RequestContextStorage is the last thing I wanna see for MDC. 😢 If exporting is only the problem, then @anuraaga 's suggestion looks good to me.

[ikhoon]

Perhaps we can allow wildcard for custom keys too using some simple mapping

+1, Nice idea

[trustin]

Perhaps we can allow wildcard for custom keys too using some simple mapping

A user still needs to copy each MDC property individually with explicit AttributeKey definitions. How about providing a way to explode a map attribute? e.g.

static final AttributeKey<Map<String, String>> MDC_ATTR = AttributeKey.valueOf(...);
ctx.setAttr(MDC_ATTR, MDC.getCopyOfContextMap());

<export>attr_map:com.example.LogKeys#MDC</export>
<export>prefix=attr_map:com.example.LogKeys#MDC</export>

[trustin]

One problem with the idea of using RequestContextExportingAppender is that it may be too much for users (including @okue) who want to use Armeria only for the client side.

In @okue's case, he uses pure Spring Webflux on the server side, propagating MDC using Reactor hooks, which is probably similar to the simplicity of using a custom RequestContextStorage - just defining and adding a hook.

That being said, I wonder if it's a good idea to add some common hooks API for RequestContextStorage, e.g. RequestContextStorage.hook(Function<RequestContextStorage, RequestContextStorage>)

[ikhoon]

That being said, I wonder if it's a good idea to add some common hooks API for RequestContextStorage, e.g. RequestContextStorage.hook(Function<RequestContextStorage, RequestContextStorage>)

+1, That sounds good to me. And How about adding lambda style event listeners. It seems to be easier to use for a simple case.

RequestContextStorage.hook(Consumer<RequestContext> onPush, Consumer<RequestContext> onPop) 

[trustin]

I wonder if it's a good idea to add some common hooks API for RequestContextStorage, e.g. RequestContextStorage.hook(Function<RequestContextStorage, RequestContextStorage>)

I tried this but I wasn't sure I'm going into the right direction because:

• When MDC properties are captured is limited to when a context is pushed. A user might want to copy an MDC property after ctx.push(), especially for the server side (but not limited to the server side - imagine you write a client-side decorator). He or she might also want to update the captured MDC property:

  // This will be captured by ctx.push() below:
  MDC.put("foo", "1234");
  try (ignored = ctx.push()) {
    // But there's no way to capture this:
    MDC.push("txid", "1234");
    // ... situation has changed ...
    // But there's no way to update the captured value:
    MDC.put("foo", "5678");
  }

• What we have to do when a context is popped is ambiguous and sometimes hard to reason.
• It's hard to handle the nested contexts such as the following. Although not impossible, I'm not sure it's worth the complexity.

  try (ignored = sctx.push()) {
  try (ignored = cctx.push()) {
    try (ignored = sctx.push()) {
      try (ignored = cctx.push()) {
        try (ignored = sctx.push()) { ... }
      }
    }
  }
  }

Therefore, I came back to the idea at https://github.com/line/armeria/issues/2634#issuecomment-625637235

The initial feedback from @anuraaga was that it's not a good idea to add another API similar to the current attribute API. Then how about not providing such API in RequestContext but in a separate utility class? e.g.

public class RequestScopedMdc { // We provide this class.
  private static final AttributeKey<Map<String, String>> MDC_ATTR_KEY = ...;

  static {
    // Intercept MDC operations.
    MDC.mdcAdapter = new OurMdcAdapterImpl(MDC.mdcAdapter);
  }

  public static void import(String prop, RequestContext ctx) {
    ctx.attr(MDC_ATTR_KEY).put(prop, MDC.get(prop));
  }
}

// User code:
MDC.put("txid", "1234");
...
try (ignorable = Clients.withContextCustomizer(ctx -> {
    RequestScopedMdc.import("txid", ctx);
    // or
    RequestScopedMdc.importAll(ctx);
    // Note: A user can write a decorator to remove the need for
    //       withContextCustomizer().
})) {
    client.execute(...);
}

// Later in another thread:
assert MDC.get("txid") == null;
try (ignored = ctx.push()) {
  // Now fetched from thread-local context's MDC_ATTR_KEY attr:
  assert MDC.get("txid").equals("1234"); 
}
// thread-local context has been popped, so 'txid' is gone:
assert MDC.get("txid") == null;

This is better than the previous idea because:

• It doesn't add anything to RequestContext API. Just one utility class.
• A user doesn't have to modify Logback configuration, which can take too much for a client-only user who seeks for a less invasive solution.

[trustin]

Created #2723 and #2724. PTAL :wink:

[trustin]

Thanks everyone for valuable feed back :heart: