How to correlate log events in distributed Vertx system

Question

while doing logs in the multiple module of vertx, it is a basic requirement that we should be able to correlate all the logs for a single request.

as vertx being asynchronous what will be the best place to keep logid, conversationid, eventid.

any solution or patterns we can implement?

I was planning to use slf4j MDC in my rest application which is using vertx framework. What I read here is that you shouldn't use MDC in vertx as MDC is thread specific and vertx is thread agnostic. But I am setting MDC variables at the start of a service which is called from one of the verticles and calling MDC.clear() at the end of the service. I think it will be within one thread - end to end event processing for one event It works fine locally but i am concerned whether it will be accurate in Production environment with thousands of messages coming every minute. someone guide please. — Sammy Pawar, Feb 22 '19 at 10:46
check this out https://reactiverse.io/reactiverse-contextual-logging/#_propagation — Charlie, Dec 10 '22 at 14:07

score 7 · Answer 1 · answered Apr 10 '18 at 14:07

In a thread based system, you current context is held by the current thread, thus MDC or any ThreadLocal would do.

In an actor based system such as Vertx, your context is the message, thus you have to add a correlation ID to every message you send.

For any handler/callback you have to pass it as method argument or reference a final method variable.

For sending messages over the event bus, you could either wrap your payload in a JsonObject and add the correlation id to the wrapper object

vertx.eventBus().send("someAddr", 
  new JsonObject().put("correlationId", "someId")
                  .put("payload", yourPayload));

or you could add the correlation id as a header using the DeliveryOption

//send
vertx.eventBus().send("someAddr", "someMsg", 
            new DeliveryOptions().addHeader("correlationId", "someId"));

//receive    
vertx.eventBus().consumer("someAddr", msg -> {
        String correlationId = msg.headers().get("correlationId");
        ...
    });

There are also more sophisticated options possible, such as using an Interceptor on the eventbus, which Emanuel Idi used to implement Zipkin support for Vert.x, https://github.com/emmanuelidi/vertx-zipkin, but I'm not sure about the current status of this integration.

The zipkin support implementation gave me the pointers I needed to get the interceptor method working, which ends up being very little code. — Clive Evans, Jun 03 '20 at 15:51

score 6 · Answer 2 · answered Jun 03 '20 at 15:49

There's a surprising lack of good answers published about this, which is odd, given how easy it is.

Assuming you set the correlationId in your MDC context on receipt of a request or message, the simplest way I've found to propagate it is to use interceptors to pass the value between contexts:

vertx.eventBus()
        .addInboundInterceptor(deliveryContext -> {
            MultiMap headers = deliveryContext.message().headers();
            if (headers.contains("correlationId")) {
                MDC.put("correlationId", headers.get("correlationId"));
                deliveryContext.next();
            }
        })
        .addOutboundInterceptor(deliveryContext -> {
            deliveryContext.message().headers().add("correlationId", MDC.get("correlationId"));
            deliveryContext.next();
        });

This should work even if your verticles aren't running in the same jvm. — Clive Evans, Jun 03 '20 at 15:52

score 1 · Answer 3 · answered Jul 12 '17 at 06:28

If by multiple module you mean multiple verticles running on the same Vertx instance, you should be able to use a normal logging library such as SLF4J, Log4J, JUL, etc. You can then keep the logs in a directory of your choice, e.g. /var/logs/appName.

If, however, you mean how do you correlate logs between multiple instances of Vertx, then I'd suggest looking into GrayLog or similar applications for distributed/centralised logging. If you use a unique ID per request, you can pass that around and use it in the logs. Or depending on your authorization system, if you use unique tokens per request you can log those. The centralised logging system can be used to aggregate and filter logs based on that information.

We already have splunk where logs are indexed and maintained. We are using unique ID per request, so to search the logs for a particular request each log statement should have access to unique request id. As vertx is async and might create multiple threads so only solution for now is to pass around the unique request id to all the places in the code where we want to log. My question was for any other out of the box solution or better approach to this? — Kishore Tulsiani, Jul 12 '17 at 18:58

score 1 · Answer 4 · answered Dec 10 '22 at 14:07

Surprised no one mentioned this Reactiverse project Contextual logging for Eclipse Vert.x

From their page:

In traditional Java development models (e.g. Spring or Java EE), the server implements a one thread per request design. As a consequence, it is possible to store contextual data in ThreadLocal variables and use it when logging. Both logback and log4j2 name this Mapped Diagnostic Context (MDC).

Vert.x implements the reactor pattern. In practice, this means many concurrent requests can be handled by the same thread, thus preventing usage of ThreadLocals to store contextual data.

This project uses an alternative storage method for contextual data and makes it possible to have MDC logging in Vert.x applications.

This is absolutely the way to go if you want something like MDC for VertX. It also contains a suggestion how to pass the data via event bus and works like a charm. — Brandon Flowers, Mar 07 '23 at 13:16

Stempler · Answer 5 · 2022-03-30T11:13:33.847

The interceptor example presented by Clive Evans works great. I added a more details example showing how this might work:

import io.vertx.core.AbstractVerticle;
import io.vertx.core.DeploymentOptions;
import io.vertx.core.MultiMap;
import io.vertx.core.Promise;
import io.vertx.core.Vertx;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;

import java.time.Duration;
import java.util.UUID;

public class PublisherSubscriberInterceptor {

  private static final Logger LOG = LoggerFactory.getLogger(PublisherSubscriberInterceptor.class);
  public static final String ADRESS = "sender.address";


  public static void main(String[] args) {
    Vertx vertx = Vertx.vertx();
    createInterceptors(vertx);

    vertx.deployVerticle(new Publisher());
    vertx.deployVerticle(new Subscriber1());

    //For our example lets deploy subscriber2 2 times.
    vertx.deployVerticle(Subscriber2.class.getName(), new DeploymentOptions().setInstances(2));
  }

  private static void createInterceptors(Vertx vertx) {
    vertx.eventBus()
      .addInboundInterceptor(deliveryContext -> {
        MultiMap headers = deliveryContext.message().headers();
        if (headers.contains("myId")) {
          MDC.put("myId", headers.get("myId"));
          deliveryContext.next();
        }
      })
      .addOutboundInterceptor(deliveryContext -> {
        deliveryContext.message().headers().add("myId", MDC.get("myId"));
        deliveryContext.next();
      });
  }

  public static class Publisher extends AbstractVerticle {

    @Override
    public void start(Promise<Void> startPromise) throws Exception {
      startPromise.complete();
      vertx.setPeriodic(Duration.ofSeconds(5).toMillis(), id -> {
        MDC.put("myId", UUID.randomUUID().toString());
      vertx.eventBus().publish(Publish.class.getName(), "A message for all");
      });
    }
  }

  public static class Subscriber1 extends AbstractVerticle {
    private static final Logger LOG = LoggerFactory.getLogger(Subscriber1.class);

    @Override
    public void start(Promise<Void> startPromise) throws Exception {
      startPromise.complete();
      vertx.eventBus().consumer(Publish.class.getName(), message-> {
        LOG.debug("Subscriber1 Received: {}", message.body());
      });
    }
  }

  public static class Subscriber2 extends AbstractVerticle {
    private static final Logger LOG = LoggerFactory.getLogger(Subscriber2.class);

    @Override
    public void start(Promise<Void> startPromise) throws Exception {
      startPromise.complete();
      vertx.eventBus().consumer(Publish.class.getName(), message-> {
        LOG.debug("Subscriber2 Received: {}", message.body());
      });
    }
  }
}

you can see the log example for publishing 2 messages:

    13:37:14.315 [vert.x-eventloop-thread-3][myId=a2f0584c-9d4e-48a8-a724-a24ea12f7d80] DEBUG o.s.v.l.PublishSubscribeInterceptor$Subscriber2 - Subscriber2 Received: A message for all
    13:37:14.315 [vert.x-eventloop-thread-1][myId=a2f0584c-9d4e-48a8-a724-a24ea12f7d80] DEBUG o.s.v.l.PublishSubscribeInterceptor$Subscriber1 - Subscriber1 Received: A message for all
    13:37:14.315 [vert.x-eventloop-thread-4][myId=a2f0584c-9d4e-48a8-a724-a24ea12f7d80] DEBUG o.s.v.l.PublishSubscribeInterceptor$Subscriber2 - Subscriber2 Received: A message for all
    13:37:19.295 [vert.x-eventloop-thread-1][myId=63b5839e-3b0b-43a5-b379-92bd1466b870] DEBUG o.s.v.l.PublishSubscribeInterceptor$Subscriber1 - Subscriber1 Received: A message for all
    13:37:19.295 [vert.x-eventloop-thread-3][myId=63b5839e-3b0b-43a5-b379-92bd1466b870] DEBUG o.s.v.l.PublishSubscribeInterceptor$Subscriber2 - Subscriber2 Received: A message for all
    13:37:19.295 [vert.x-eventloop-thread-4][myId=63b5839e-3b0b-43a5-b379-92bd1466b870] DEBUG o.s.v.l.PublishSubscribeInterceptor$Subscriber2 - Subscriber2 Received: A message for all

score -1 · Answer 6 · answered Oct 29 '19 at 07:51

-1

Use vertx-sync and a ThreadLocal for the correlation ID. (i.e., a "FiberLocal"). Works great for me.

answered Oct 29 '19 at 07:51

DoctorPangloss

2,994
1
18
22

How to correlate log events in distributed Vertx system

6 Answers6

Linked

Related