We recently migrated from Splunk to ELK. We wanted to log our message as json for better searchability in Kibana.
Our application was using vert.x 3.9. I came across https://reactiverse.io/reactiverse-contextual-logging but that requires vertx-core to be updated to 4.x. This will be a major change for us and I looked for other options. Also, I joined this team recently and new to Vert.x
I came across net.logstash.logback:logstash-logback-encoder and able to log the messages as json. I used io.vertx.core.json.JsonObject to convert my message and key values to convert to json. I created a wrapper class that returns the string for given message and key/values as shown below.
public class KeyValueLogger {
public static String getLog(final String message) {
return new JsonObject().put("message", message).encode();
}
public static String getLog(final String message, final Map<String, Object> params) {
return new JsonObject().put("message", message).mergeIn(new JsonObject(params)).encode();
}
}
Every log message will call the above KeyValueLogger.getLog to get json message. Since Vert.x is a reactive application, is there a better solution to convert the log messages to json? Most of the log messages are in worker threads. I am afraid if any is in event loop thread then it might impact the performance.
Thanks in advance!
CodePudding user response：
I am able to use logstash-logback-encoder by referring to https://github.com/logfellow/logstash-logback-encoder/tree/logstash-logback-encoder-6.6#readme in section Examples using Markers: . This eliminated custom code to convert the message and key values conversion to json. I tested the performance and it is really good and no need of reactive/async for my use case.
Sample Code
import java.util.Map;
import static net.logstash.logback.marker.Markers.appendEntries;
@Test
public void logTest(){
Map<String, String> map = ImmutableMap.of("p1", "v1", "p2", "v2");
log.info(appendEntries(map), "startTest 100");
log.info("startTest {} , key1={}, key2= {}", 101, "v1", "v2");
log.info(appendEntries(map), "startTest {} , key1={}, key2= {}", 101, "v1", "v2");
log.info("startTest 102");
log.error(appendEntries(map), "error occured", new RuntimeException());
}
Sample logback configuration
Note: <logstashMarkers/> is required to log the Map as key values in the json log output.
<appender name="console" >
<encoder >
<providers>
<timestamp/>
<logLevel/>
<contextName/>
<threadName>
<fieldName>thread</fieldName>
</threadName>
<callerData>
<fieldName>src</fieldName>
<classFieldName>class</classFieldName>
<methodFieldName>method</methodFieldName>
<fileFieldName>file</fileFieldName>
<lineFieldName>line</lineFieldName>
</callerData>
<logstashMarkers/>
<pattern>
<pattern>
{
"message": "%message"
}
</pattern>
</pattern>
<stackTrace>
<throwableConverter >
<maxDepthPerThrowable>30</maxDepthPerThrowable>
<maxLength>2048</maxLength>
<shortenedClassNameLength>20</shortenedClassNameLength>
<exclude>^sun\.reflect\..*\.invoke</exclude>
<exclude>^net\.sf\.cglib\.proxy\.MethodProxy\.invoke</exclude>
<rootCauseFirst>true</rootCauseFirst>
</throwableConverter>
</stackTrace>
</providers>
</encoder>
</appender>
Performance test
Added the following performance test and it took ~ 0.08286483 milli seconds = 82864.8304 nano seconds per log message on average.
private static Map<String, Object> getMap(){
int count = 5;
Map<String, Object> map = new HashMap<String, Object>();
for(int i=0; i<count; i){
map.put("key" i, UUID.randomUUID());
}
return map;
}
@Test
public void logPerformanceTest(){
long startTime = System.nanoTime();
final int COUNT = 10000;
for(int i=0; i<COUNT; i ) {
log.info(appendEntries(getMap()), "startTest 100");
}
long time = System.nanoTime() - startTime;
System.out.println("###### TOOK " time " (ns) ");
}
CodePudding user response：
There might be a better solution to convert the log messages to JSON in Vert.x. One option could be using the Vert.x event bus to send log messages from worker threads to a dedicated logger verticle. This way, the logger verticle can handle the JSON conversion and logging, freeing up the worker threads from performing additional tasks.
This approach also ensures that the logging process does not impact the performance of the event loop thread, as it's running in a separate verticle.
First, you need to create a logger verticle that will handle the JSON conversion and logging. This verticle can subscribe to a specific address on the event bus to receive log messages. The logger verticle can look like this:
public class LoggerVerticle extends AbstractVerticle {
@Override
public void start() {
EventBus eventBus = vertx.eventBus();
eventBus.consumer("logger.address", message -> {
JsonObject logMessage = (JsonObject) message.body();
// Convert log message to JSON format and log it
System.out.println(logMessage.encodePrettily());
});
}
}
Next, in your worker threads, you can send log messages to the logger verticle using the event bus. To send a log message, you can create a JsonObject with the log message and other key-value pairs, and then send it to the logger.address on the event bus.
Map<String, Object> params = new HashMap<>();
params.put("timestamp", System.currentTimeMillis());
params.put("worker-thread", Thread.currentThread().getName());
JsonObject logMessage = new JsonObject(params);
logMessage.put("message", "Log message from worker thread");
EventBus eventBus = vertx.eventBus();
eventBus.send("logger.address", logMessage);
Finally, you need to deploy the logger verticle in your Vert.x application, so that it starts receiving log messages.
Vertx vertx = Vertx.vertx();
vertx.deployVerticle(new LoggerVerticle());
This way, you can ensure that log messages are converted to JSON format before logging and that the logging process does not impact the performance of the event loop thread.
It's like having a dedicated chef to cook the dishes and serve them, freeing up the waiter to focus on taking orders and managing the restaurant.