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 Splunk, GreyLog, or LogStash. This allows the MDC fields to be used for real-time operational intelligence using tools like Splunk, LogStash 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 requestRemoteAddress, requestUri, 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 MethodCall, HttpRequest, WebSocketMessage, Event 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"
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 Programming, Java Microservices, Rick 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!
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
