Logging with Vert.x — part 2. In part 1, we talked about how to use… | by Guozheng Ge

3 min readMar 18, 2020

Logging with Vert.x — part 2

In part 1, we talked about how to use logging frameworks other than the default JUL in Vert.x. In this part 2, we will focus on request logging for Vert.x.

Request log or access log stores information about incoming HTTP requests. There are two common formats: NCSA Common Log Format (CLF) and W3C Extended Log Format (ELF). Each line records data for one request. Each format specification defines fields like timestamp, client ip, url, method, response status, etc. Users select and list what goes into each request log line.

For example:

125.0.0.1 - [10/Oct/2011:13:55:36 -0700] "GET /examp_alt.png HTTP/1.0" 200 10801 Mozilla/4.0  (compatible: MSIE+5.5+Windows+2000+Server)

We have these fields in the above example:

client ip
- means missing data, not able to find from request
timestamp
HTTP method and URI
response status code
response byte size
user agent

Vert.x comes with a default request logger via two classes: LoggerHandler interface and LoggerHandlerImpl class that implements the interface.

To use that, you can simply add it to your route handlers:

...
Router router = Router.router(vertx);router.route().handler(BodyHandler.create());
router.route().handler(TimeoutHandler.create(100));
router.route().failureHandler(ErrorHandler.create(false));...
router.route().handler(LogHandler.create());

But one problem we found is that it somehow does not play well with Slf4j+logXYZ combination. Only the logger created via Slf4j writes log into the configured log files. The default Vert.x logger does not use Slf4j, so it still goes to the JUL logger based on its configuration.

Another missing feature for our use case is that we have POST requests and we want to log POST body in the request log.

Attempt 1: use an existing open source request logger

The first reaction is that someone must have built the wheel already, so let me search for it. Luckily I found this nice wheel:

vertx-web-accesslog: a request logger implementation that supports multiple appenders including console, event bus, elastic search and logging framework appenders.
vertx-web-accesslog-logging-appender: logging appender that supports multiple logging frameworks.

There are several tricks to use it:

two configurations: one for vertx-web-accesslog-logging-appender, the other for the logging framework (log4j, log4j2, logback, etc.).
appender pattern needs to be in sync in both configurations.
logger name needs to be in sync in both configurations.
log file needs to be in sync in both configurations.

Since we need to log request body, although this is a nice solution, we ended up taking the Attempt 2.

Attempt 2: Implement your own request logger

We ended up copying the Vertx’s LoggerHandler idea, but customize the three predefined formats differently: DEFAULT, SHORT, TINY. It gives us a lot of flexibility to log anything related to the request.

RequestLogHandler.java is similar to LoggerHandler.java:

package io.woshiadai.starter;

import io.vertx.codegen.annotations.VertxGen;
import io.vertx.core.Handler;
import io.vertx.ext.web.RoutingContext;
import io.vertx.ext.web.handler.LoggerFormat;

@VertxGen
public interface RequestLogHandler extends Handler<RoutingContext> {
  static RequestLogHandler create() {
    return new Slf4jRequestLogger(LoggerFormat.DEFAULT);
  }

  static RequestLogHandler create(LoggerFormat format) {
    return new Slf4jRequestLogger(format);
  }
}

Slf4jRequestLogger.java is similar to LoggerHandlerImpl.java, the most interesting part is here, we can control what to log for three formats as we needed:

...
MultiMap headers = request.headers();
int status = request.response().getStatusCode();
String message = null;
switch (this.format) {
  case DEFAULT:
    String referrer = headers.contains("referrer") ? headers.get("referrer") : headers.get("referer");
    String userAgent = headers.get("user-agent");
    String body = context.getBodyAsString().replaceAll("(\\r|\\n)", "");
    referrer = referrer == null ? "-" : referrer;
    userAgent = userAgent == null ? "-" : userAgent;
    message = String.format("%s - - [%s] \"%s %s %s\" %d %d \"%s\" \"%s\" %dms %s",
        remoteClient,
        this.dateTimeFormat.format(new Date(timestamp)),
        method,
        uri,
        versionFormatted,
        status,
        contentLength,
        referrer,
        userAgent,
        System.currentTimeMillis() - timestamp,
        body);
    break;
  case SHORT:
    message = String.format("%s - - [%s] \"%s %s %s\" %d %d \"%s\" \"%s\" %dms",
        remoteClient,
        this.dateTimeFormat.format(new Date(timestamp)),
        method,
        uri,
        versionFormatted,
        status,
        contentLength,
        headers.contains("referrer") ? headers.get("referrer") : headers.get("referer"),
        headers.get("user-agent"),
        System.currentTimeMillis() - timestamp);
    break;
  case TINY:
    message = String.format("%s - %s %s %d %d",
        remoteClient,
        method,
        uri,
        status,
        contentLength);
    break;
  default:
    message = String.format("%s - %s %s %d %d",
        remoteClient,
        method,
        uri,
        status,
        contentLength);
    break;
}
...

To use our own request logger, just add it to route handlers:

// use customized request logger
// there are three logger format: DEFAULT, SHORT, TINY, see Slf4jRequestLogger.java for details
// you can make it configurable, e.g. dev using DEFAULT, prod using TINY
LoggerFormat loggerFormat = LoggerFormat.DEFAULT;
router.route().handler(RequestLogHandler.create(loggerFormat));

For more details, you can see the code here.

Written by Guozheng Ge