Microservices distributed logging and MDC (Logging Mapped Diagnostic Context)

posted Nov 24, 2015, 4:20 PM by Rick Hightower   [ updated Nov 24, 2015, 4:27 PM ]
In the past we wrote about the importance of monitoring and statistics with Microservices Architecture. Certainly we have put our time and money where we speak, as QBit, the microservice library for Java, has support health checks, and statistics built-in which is both queryable/actionable/reactive and can also be stored in time series databases readily with its support for StatsD and its pluggable monitoring architecture.  

But another aspect of microservices monitoring is ability to use distributed logging in a searchable format. In order to do this and to really debug and track services one needs to use Mapped Diagnostic Context (MDC) with logging. MDC is extremely important for debugging and understanding microservices. Developing microservices without MDC and distributed log analysis is like flying blind. 

QBit, microservices lib, has implemented the Logging Mapped Diagnostic Context (MDC). Prior to MDC integration it was difficult to track request information in logs. Now we have added MDC integration it is easy to track Request URI, and more.

We added support for MDC to log the requests coming from Microservice you write like:

  • UserID
  • First name, last name
  • Request URI
  • remote address
  • browser/use-agent

For microservice to microservice calls (service to service) we can track the URI, source IP of the system, request URI. You should also be able to track (or set) any extra headers that will make sense to log in the context of the application.

This allows you to customize the Pattern used to log - and allows items to be properly pushed to SplunkGreyLog, or LogStash. This allows the MDC fields to be used for real-time operational intelligence using tools like SplunkLogStash and GreyLog. This allows you to search, analyze and log streams from your microservices log to learn about usages of these services which is critical for debugging and learning about how your microservices are used. Distributed logging and distributed log analysis is sort of a given in a microservices architecture.

Modern logging systems are designed to audit and debug distributed applications. QBit being a reactive microservice lib allows the creation of in-proc services and remote services, i.e., distributed applications. The in-proc services run in one or more threads using an actor/service queue model. QBit MDC support crosses the Thread/Queue/Actor Message boundary to facilitated debugging and provide a complete async call stack which is essential for debugging a message passing system like QBit which relies of ServiceQueue's.

Since QBit, the microservices lib, focuses on creating distributed systems you have to deal with multiple clients simultaneously when dealing with logging and auditing. The concepts of MDC (Mapped Diagnostic Contexts) was covered in the book Logging Diagnostic Messages in Pattern Languages of Program Design 3, by Neil Harrison (Addison-Wesley, 1997). QBit uses SLF4J API for Mapped Diagnostic Contexts (MDC).

Examples of using MDC

QBit provides the class ManagedServiceBuilder which is a utility class for when you are running in a PaaS like Heroku or Docker. It also allows you to share stat, health and system manager setup. You can also do things like enable stats (statsD support baked in), and install service discovery / distributed health (Consul, SkyDNS), etc.

The ManagedServiceBuilder to support MDC now provides a method enableLoggingMappedDiagnosticContext(). This installs the correct QBit interceptors to provide MDC logging and to create an async service call stack.

Let's demonstrate how this works with a simple example RestService.

RestService example to demonstrate MDC

@RequestMapping ("rest")
public class RestService {

    private final Logger logger = LoggerFactory.getLogger(RestService.class);

...

    @RequestMapping ("mdc")
    public void mdc(final Callback<Map<String,String>> callback) {
        logger.info("CALLED MDC");
        callback.returnThis(MDC.getCopyOfContextMap());
    }
...

To make mdc work for the log, we will add the logback.xml file to the Java resources.

/resources/logback.xml

<configuration>

    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n- 
%X{requestRemoteAddress} - %X{requestUri} - %X{requestHttpMethod}%n</pattern>
        </encoder>
    </appender>


    <logger name="io.advantageous.qbit" level="DEBUG"/>

    <root level="INFO">
        <appender-ref ref="STDOUT"/>
    </root>
</configuration>

Notice the syntax %X{requestRemoteAddress}, this allows you to access the current HTTP request's remote address.

When constructing this service, you have to call enableLoggingMappedDiagnosticContext.

Turning on MDC support for ManagedServiceBuilder

        final ManagedServiceBuilder managedServiceBuilder = ManagedServiceBuilder.managedServiceBuilder();
        managedServiceBuilder.setRootURI("/");
        managedServiceBuilder.enableLoggingMappedDiagnosticContext();

        final RestService restService = new RestService();

        managedServiceBuilder.addEndpointService(restService);


        managedServiceBuilder.getEndpointServerBuilder().build().startServer();

At this point you can access the service with curl as follows:

Accessing the service with curl to see mdc

 curl http://localhost:8080/rest/mdc | jq .
{
  "requestRemoteAddress": "0:0:0:0:0:0:0:1:63772",
  "requestUri": "/rest/mdc",
  "requestHttpMethod": "GET"
}

Output of log

18:57:00.516 [QueueListener|Send Queue  rest] INFO  i.a.qbit.example.mdc.RestService - CALLED MDC
- 0:0:0:0:0:0:0:1:63797 - /rest/mdc - GET

Notice that the requestRemoteAddressrequestUri, and requestHttpMethod was output to the log.

Note that the enableLoggingMappedDiagnosticContext allows you to pass in N number of header names which will become part of the logging MDC and if you are using Splunk, GreyLog or LogStash will become part of the custom fields that you can parse. Once you use LogStash, Splunk or GreyLog with custom fields for headers, and requests etc. for debugging and log analysis, you will not know how you did it without it.

This is important and nice. But what if you have downstream services, i.e., ServiceQueue service or a ServiceBundle service. These services are running on other threads. Will QBit pass handle this case? Yes. Yes it will.

Downstream services example

To show QBit's ability to breach the thread chasm of other actor service queues, let's create some services.

And, in addition let's show off RequestContext which QBit uses to create this context by creating a service queue call stack to show the call stack.

Service to show capturing service call stack and MDC working N-levels deep

public interface InternalService {

    void getCallStack(Callback<List<String>> listCallback);
}

....


public class InternalServiceImpl {


    private final Logger logger = LoggerFactory.getLogger(InternalServiceImpl.class);
    private final RequestContext requestContext;

    public InternalServiceImpl(final RequestContext requestContext) {
        this.requestContext = requestContext;
    }

    public List<String> getCallStack() {

        logger.info("GET CallStack called");

        final Optional<MethodCall<Object>> currentMethodCall = requestContext.getMethodCall();

        if (!currentMethodCall.isPresent()) {
            logger.info("Method not found");
            return Arrays.asList("MethodCall Not Found");
        }

        final List<String> callStack = new ArrayList<>();
        MethodCall<Object> methodCall = currentMethodCall.get();
        callStack.add("Service Call(" + methodCall.objectName()
                + "." + methodCall.name() + ")");

        while (methodCall!=null) {

            final Request<Object> request = methodCall.originatingRequest();
            if (request ==null) {
                methodCall = null;
            } else if (request instanceof MethodCall) {
                methodCall = ((MethodCall<Object>) request);
                callStack.add("Service Call(" + methodCall.objectName()
                        + "." + methodCall.name() + ")");
            } else if (request instanceof HttpRequest) {
                final HttpRequest httpRequest = ((HttpRequest) request);

                callStack.add("REST Call(" + httpRequest.getRemoteAddress()
                        + "." + httpRequest.getUri() + ")");

                methodCall = null;
            } else {
                methodCall = null;
            }
        }

        return callStack;
    }

}

Now let's wire in this service twice. Once being used from a ServiceQueue (fastest) and once using a ServiceBundle. Notice the above calls logger.info("GET CallStack called"), and then it uses requestContext.getMethodCall() to get the current MethodCall in QBit. Note that a MethodCall is a Request in QBit, and an HttpRequest is a Request as well. You can now track the current MethodCall all the way back to the HttpRequest using the request.originatingRequest() method as shown above. We use originatingRequest to find the original HttpRequest and all of the MethodCall's in-between.

Wiring in InternalServiceImpl to show service queue call stack and logging mdc

    public static void main(String... args) throws Exception {
        final ManagedServiceBuilder managedServiceBuilder = ManagedServiceBuilder.managedServiceBuilder();


        managedServiceBuilder.setRootURI("/");

        managedServiceBuilder.enableLoggingMappedDiagnosticContext();

        /** Create Service from Service Queue. */
        final InternalService internalServiceFromServiceQueue = getInternalServiceFromServiceQueue(managedServiceBuilder);


        /** Create Service from Service Bundle. */
        final InternalService internalServiceFromServiceBundle = getInternalServiceFromServiceBundle(managedServiceBuilder);


        final StatsCollector statsCollectorForRest = managedServiceBuilder.getStatServiceBuilder().buildStatsCollector();

        final RestService restService = new RestService(internalServiceFromServiceBundle,
                internalServiceFromServiceQueue,
                ReactorBuilder.reactorBuilder().build(), Timer.timer(), statsCollectorForRest);

        managedServiceBuilder.addEndpointService(restService);


        managedServiceBuilder.getEndpointServerBuilder().build().startServer();


    }

    private static InternalService getInternalServiceFromServiceQueue(ManagedServiceBuilder managedServiceBuilder) {
        final InternalServiceImpl internalServiceImpl = new InternalServiceImpl(new RequestContext());
        final ServiceBuilder serviceBuilderForServiceObject = managedServiceBuilder.createServiceBuilderForServiceObject(internalServiceImpl);
        final ServiceQueue serviceQueue = serviceBuilderForServiceObject.buildAndStartAll();
        return serviceQueue.createProxy(InternalService.class);
    }


    private static InternalService getInternalServiceFromServiceBundle(ManagedServiceBuilder managedServiceBuilder) {
        final InternalServiceImpl internalServiceImpl = new InternalServiceImpl(new RequestContext());
        final ServiceBundle serviceBundle = managedServiceBuilder.createServiceBundleBuilder().build().startServiceBundle();
        serviceBundle.addServiceObject("myService", internalServiceImpl);
        return serviceBundle.createLocalProxy(InternalService.class, "myService");
    }

Then we use these services from the RestService example that we created to show a call stack from a ServiceQueue and a call stack from a ServiceBundle.

Using services to show call stack from ServiceQueue andServiceBundle.

@RequestMapping ("rest")
public class RestService extends BaseService {

    private final Logger logger = LoggerFactory.getLogger(RestService.class);
    private final InternalService internalServiceFromServiceQueue;
    private final InternalService internalServiceFromServiceBundle;

    public RestService(final InternalService internalServiceFromServiceBundle,
                       final InternalService internalServiceFromServiceQueue,
                       final Reactor reactor,
                       final Timer timer,
                       final StatsCollector statsCollector) {
        super(reactor, timer, statsCollector);
        this.internalServiceFromServiceBundle = internalServiceFromServiceBundle;
        this.internalServiceFromServiceQueue = internalServiceFromServiceQueue;
        reactor.addServiceToFlush(internalServiceFromServiceBundle);
        reactor.addServiceToFlush(internalServiceFromServiceQueue);
    }

    @RequestMapping ("callstack/queue")
    public void callStackFromQueue(final Callback<List<String>> callback) {
        logger.info("Logger {}", MDC.getCopyOfContextMap());
        internalServiceFromServiceQueue.getCallStack(callback);
    }

    @RequestMapping ("callstack/bundle")
    public void callStackFromBundle(final Callback<List<String>> callback) {
        logger.info("Logger {}", MDC.getCopyOfContextMap());
        internalServiceFromServiceBundle.getCallStack(callback);
    }

Now let's call this service with REST and see the results.

Calling REST service to see example service queue call stack

$ curl http://localhost:8080/rest/callstack/queue | jq .
[
  "Service Call(.getCallStack)",
  "Service Call(restservice.callStackFromQueue)",
  "REST Call(0:0:0:0:0:0:0:1:63881./rest/callstack/queue)"
]

Calling REST service to see example service bundle call stack

$ curl http://localhost:8080/rest/callstack/bundle | jq .
[
  "Service Call(myService.getCallStack)",
  "Service Call(restservice.callStackFromBundle)",
  "REST Call(0:0:0:0:0:0:0:1:63899./rest/callstack/bundle)"
]

Output

19:20:12.807 [QueueListener|Send Queue  rest] INFO  i.a.qbit.example.mdc.RestService - Logger {requestRemoteAddress=0:0:0:0:0:0:0:1:63909, requestUri=/rest/callstack/queue, requestHttpMethod=GET}
- 0:0:0:0:0:0:0:1:63909 - /rest/callstack/queue - GET

19:20:12.808 [QueueListener|Send Queue  internalserviceimpl] INFO  i.a.q.e.mdc.InternalServiceImpl - GET CallStack called
- 0:0:0:0:0:0:0:1:63909 - /rest/callstack/queue - GET

19:20:14.906 [QueueListener|Send Queue  rest] INFO  i.a.qbit.example.mdc.RestService - Logger {requestRemoteAddress=0:0:0:0:0:0:0:1:63910, requestUri=/rest/callstack/bundle, requestHttpMethod=GET}
- 0:0:0:0:0:0:0:1:63910 - /rest/callstack/bundle - GET

19:20:14.958 [QueueListener|Send Queue  /services/myService] INFO  i.a.q.e.mdc.InternalServiceImpl - GET CallStack called
- 0:0:0:0:0:0:0:1:63910 - /rest/callstack/bundle - GET

Think about this for a moment. We just passed our call context and we jumped the Thread call context chasm. Pretty cool?

Getting the current request context

You do not have to call ManagedServiceBuilder.enableLoggingMappedDiagnosticContext to get the request context. All you need to call is enableRequestChain. Calling enableRequestChain enables the request chain. There is some slight overhead for this, but this allows REST and WebSocket services to pass the originating request, methodCall, etc. to downstream services where it will be available via the RequestContext. Remember that a MethodCallHttpRequestWebSocketMessageEvent are all Requests objects in QBit. Calling ManagedServiceBuilder.enableLoggingMappedDiagnosticContext also enables ManagedServiceBuilder.enableRequestChain.

The class RequestContext allows you to access the current request or current method.

QBit's RequestContext class

package io.advantageous.qbit.service;

import io.advantageous.qbit.message.MethodCall;
import io.advantageous.qbit.message.Request;

import java.util.Optional;

/**
 * Holds the current request for the method call.
 */
public class RequestContext {
    /** Grab the current  request.
     *
     * @return Optional  request.
     */
    public Optional<Request<Object>> getRequest() {
        ...
    }

    /** Grab the current method call.
     *
     * @return Optional  method call.
     */
    public Optional<MethodCall<Object>> getMethodCall() {
       ... 
    }

...

}

In addition QBit provides a way to access the current HttpRequest associated with a service call chain. This is done via the HttpContext which extends the RequestContext.

QBit's HttpContext class

/**
 * Holds current information about the HttpRequest.
 */
public class HttpContext extends RequestContext {


    /** Grab the current http request.
     *
     * @return Optional http request.
     */
    public Optional<HttpRequest> getHttpRequest() {
        ...
    }
...

We can extend our example to capture the HttpContext. Let's add this to the RestService.

    @RequestMapping ("http-info")
    public String httpInfo() {

        final StringBuilder builder = new StringBuilder();
        final HttpContext httpContext = new HttpContext();
        final Optional<HttpRequest> httpRequest = httpContext.getHttpRequest();
        if (httpRequest.isPresent()) {
            builder.append("URI = ").append(httpRequest.get().getUri()).append("\n");
            builder.append("HTTP Method = ").append(httpRequest.get().getMethod()).append("\n");
            builder.append("USER AGENT = ").append(
                    httpRequest.get().getHeaders().getFirst(HttpHeaders.USER_AGENT)).append("\n");
        } else {
            builder.append("request not found");
        }


        final RequestContext requestContext = new RequestContext();

        if (requestContext.getMethodCall().isPresent()) {
            final MethodCall<Object> methodCall = requestContext.getMethodCall().get();
            builder.append("Object Name = ").append(methodCall.objectName()).append("\n");
            builder.append("Method Name = ").append(methodCall.name()).append("\n");
        }
        return builder.toString();
    }

The above shows how to use both HttpContext and another example of RequestContext.

$ curl http://localhost:8080/rest/http-info | jq .
"URI = /rest/http-info\nHTTP Method = GET\nUSER AGENT = curl/7.43.0\nObject Name = restservice\nMethod Name = httpInfo\n"



To read more details about QBit's MDC support read this MDC Logging Mapped Diagnostic Context for Microservices ad hoc monitoring.
We cover the design and provide more details on the above code examples. 

To learn more about microservices and QBit please read:

QBit Java Micorservices lib tutorials

The Java microservice lib. QBit is a reactive programming lib for building microservices - JSON, HTTP, WebSocket, and REST. QBit uses reactive programming to build elastic REST, and WebSockets based cloud friendly, web services. SOA evolved for mobile and cloud. ServiceDiscovery, Health, reactive StatService, events, Java idiomatic reactive programming for Microservices.

Find more tutorial on QBit.

Reactive ProgrammingJava MicroservicesRick Hightower

High-speed microservices consulting firm and authors of QBit with lots of experience with Vertx - Mammatus Technology

Highly recommended consulting and training firm who specializes in microservices architecture and mobile development that are already very familiar with QBit and Vertx as well as iOS and Android - About Objects

Java Microservices Architecture

Microservice Service Discovery with Consul

Microservices Service Discovery Tutorial with Consul

Reactive Microservices

High Speed Microservices

Java Microservices Consulting

Microservices Training

Reactive Microservices Tutorial, using the Reactor

QBit is mentioned in the Restlet blog


Quick overview of QBit

The Java microservice lib. QBit is a reactive programming lib for building microservices - JSON, HTTP, WebSocket, and REST. QBit uses reactive programming to build elastic REST, and WebSockets based cloud friendly, web services. SOA evolved for mobile and cloud. ServiceDiscovery, Health, reactive StatService, events, Java idiomatic reactive programming for Microservices.

Got a question? Ask here: QBit Google Group.

Everything is a queue. You have a choice. You can embrace it and control it. You can optimize for it. Or you can hide behind abstractions. QBit opens you up to peeking into what is going on, and allows you to pull some levers without selling your soul.

QBit is a library not a framework. You can mix and match QBit with Spring, Guice, etc.

QBit is FAST!

QBit the microservice framework for java

Core Features

  • Write REST based async microservices
  • Write Websocket based async microservices
  • Actor Service Queues using micro-batching for high-speed message passing
  • Strongly async typed event bus which can be distributed
  • Complex async call coordination (with the Reactor) for reactive programming
  • Built-in support for health checks (and integration with tools like Consul)
  • Built-in support for monitoring (and integration with wire protocols like StatsD)
  • Built-in support for Service Discovery (with integration with health system, DNS SRV records and Consul)
  • Integration with persistent queues



Comments