How can we propagate slf4j MDC/Request_id in Play framework for Java

Question

I am facing an issue on propagating slf4 MDC in play framework. I actually require to pass an X-Request-Id from request through multiple threads for the purpose of slf4 logging.

I found a solution here, https://yanns.github.io/blog/2014/05/04/slf4j-mapped-diagnostic-context-mdc-with-play-framework/ for passing MDC in an asynchronous environment. But unfortunately it's not working. After putting MDC in a filter I am getting null value in controller for that MDC. Here is my code snippts.

LoggingFilters.java

@Component
public class LoggingFilters extends Filter {
  private final Executor exec;
  public static final String REQUEST_ID_STRING = "X-Request-Id";
  private static final Logger log = LoggerFactory.getLogger(LoggingFilters.class);

  @Inject
  public LoggingFilters(final Materializer mat, final Executor exec) {
    super(mat);
    this.exec = exec;
  }

  @Override
  public CompletionStage apply(
      final Function> nextFilter,
      final Http.RequestHeader requestHeader) {
    final String requestId = requestHeader.header(REQUEST_ID_STRING).orElse(UUID.randomUUID().toString());
    MDC.put(REQUEST_ID_STRING, requestId);
    return nextFilter
        .apply(requestHeader)
        .thenApplyAsync(
            result -> {
              MDC.remove(REQUEST_ID_STRING);
              return result;
            }, exec);
  }
}

Filters.java

public class Filters implements HttpFilters {

  private final List filters;

  @Inject
  public Filters(final LoggingFilters loggingFilter) {
    filters = Lists.newArrayList(
        loggingFilter.asJava());
  }

  @Override
  public List getFilters() {
    return filters;
  }
}

MDCPropagatingDispatcherConfigurator.scala

package topl.util

import akka.dispatch._
import com.typesafe.config.Config
import org.slf4j.MDC

import java.util.concurrent.TimeUnit
import scala.concurrent.ExecutionContext
import scala.concurrent.duration.{Duration, FiniteDuration}

class MDCPropagatingDispatcherConfigurator(config: Config, prerequisites: DispatcherPrerequisites)
  extends MessageDispatcherConfigurator(config, prerequisites) {

  private val instance = new MDCPropagatingDispatcher(
    this,
    config.getString("id"),
    config.getInt("throughput"),
    FiniteDuration(config.getDuration("throughput-deadline-time", TimeUnit.NANOSECONDS), TimeUnit.NANOSECONDS),
    configureExecutor(),
    FiniteDuration(config.getDuration("shutdown-timeout", TimeUnit.MILLISECONDS), TimeUnit.MILLISECONDS))

  override def dispatcher(): MessageDispatcher = instance
}

class MDCPropagatingDispatcher(_configurator: MessageDispatcherConfigurator,
                               id: String,
                               throughput: Int,
                               throughputDeadlineTime: Duration,
                               executorServiceFactoryProvider: ExecutorServiceFactoryProvider,
                               shutdownTimeout: FiniteDuration)
  extends Dispatcher(_configurator, id, throughput, throughputDeadlineTime, executorServiceFactoryProvider, shutdownTimeout) {

  self =>

  override def prepare(): ExecutionContext = new ExecutionContext {
    // capture the MDC
    val mdcContext = MDC.getCopyOfContextMap

    def execute(r: Runnable) = self.execute(new Runnable {
      def run() = {
        // backup the callee MDC context
        val oldMDCContext = MDC.getCopyOfContextMap

        // Run the runnable with the captured context
        setContextMap(mdcContext)
        try {
          r.run()
        } finally {
          // restore the callee MDC context
          setContextMap(oldMDCContext)
        }
      }
    })

    def reportFailure(t: Throwable) = self.reportFailure(t)
  }

  private[this] def setContextMap(context: java.util.Map[String, String]) {
    if (context == null) {
      MDC.clear()
    } else {
      MDC.setContextMap(context)
    }
  }

}

Application.conf

akka {
  actor {
       default-dispatcher {
                  type = "topl.util.MDCPropagatingDispatcherConfigurator"
                }
  }
}

I have also some custom Execution Context for serving different purposes. I am also passing MDC context there too. For example: MediumExecutionContext

MediumExecutionContext.java

@Component
public class MediumExecutionContext extends CustomExecutionContext {

  public MediumExecutionContext(final ActorSystem actorSystem) {
    // uses a custom thread pool defined in application-default.conf
    super(actorSystem, "medium-dispatcher");
  }

  @Override
  public ExecutionContext prepare() {
    final Map mdcContext = MDC.getCopyOfContextMap();
    return new ExecutionContext() {
      @Override
      public void execute(final Runnable r) {
        final Map oldMDCContext = MDC.getCopyOfContextMap();
        setContextMap(mdcContext);
        try {
          r.run();
        } finally {
          setContextMap(oldMDCContext);
        }
      }

      @Override
      public ExecutionContext prepare() {
        return this;
      }

      @Override
      public void reportFailure(final Throwable t) {
        play.Logger.info("error occured in dispatcher");
      }
    };
  }

  private void setContextMap(final Map context) {
    if (context == null) {
      MDC.clear();
    } else {
      MDC.setContextMap(context);
    }
  }
}

DispatchHelper.java

public Executor getMediumExecutor() {
  return HttpExecution.fromThread((Executor)mediumExecutionContext);
}

logback.xml

  
        
            %d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} %mdc{X-Request-Id:--} - %msg%n

Controller

@Slf4j 
@RequiredArgsConstructor 
@Controller 
@GeneralOpenApiResource 
public class FetchDirectoryApi extends NewAuthenticatedInterceptorStack {

    public CompletionStage getRootDirectories(final Request request,final String category) {
            log.info("Test 1"); //I am not getting the MDC context here and it'snot logging the x-request-id 
            }
}

So, could you please help me to make this work? Or, is there any different approach that I can follow to log the request_id from some nested threads?

I have got a Fix!

Solution:

I am sharing the solution here so that it helps other.

Method Interception: Instead of Filter it's better to use a Method interceptor to store the MDC. I have followed this link to extend Action.Simple for intercepting the request in play framework.

public class DefaultAction extends Action.Simple {
```
@Override
public CompletionStage call(final Request request) {
  try {
    MDC.put("TestKey", "Test Value")
    return delegate.call(request);
  } finally {
    // Clean up the MDC
    MDC.remove("TestKey")
  }
}
```
}

Change for Custom Dispatchers: To propagate MDC context to different Dispatchers (which runs in different threads) I override the execute() method as follows.

public class MediumExecutionContext extends CustomExecutionContext {

public MediumExecutionContext(final ActorSystem actorSystem) {
  // uses a custom thread pool defined in application.conf
  super(actorSystem, "medium-dispatcher");
}

@Override
public void execute(final Runnable command) {
  final Map mdcContext = MDC.getCopyOfContextMap();
  final Runnable runnable = () -> {
    final Map oldMdcContext = MDC.getCopyOfContextMap();
    MDC.setContextMap(mdcContext);
    try {
      command.run();
    } finally {
      MDC.setContextMap(oldMdcContext);
    }
  };
  runnable.run();
}

}

Now it should propagate the MDC value through the dispatchers (in different thread).

How can we propagate slf4j MDC/Request_id in Play framework for Java

0 Answers