Logging with Vert.x — part 1

Recently, I started learning Vert.x. It really fun to use. Here are some lessons I learned regarding logging with Vert.x. The source code and a working example can be found here.

By default, Vert.x uses JUL (Java Util Logging), with the configuration file logging.properties within JDK installation. You can also set system property java.util.logging.config.file to provide your customized configuration.

In most cases, we use Slf4j+logXYZ (logback, log4j, log4j2, etc.). Vert.x allows you to set different LogDelegateFactory using system property vertx.logger-delegate-factory-class-name. Here are the supported values:

• JULLogDelegateFactory
• Log4j2LogDelegateFactory
• Log4jLogDelegateFactory
• SLF4JLogDelegate

For example, suppose that we want to use Slf4j+logback. You can add dependent libraries to your build tool, e.g. for Gradle build.gradle:

...
dependencies {
  implementation "org.slf4j:slf4j-api:1.7.+"
  implementation "ch.qos.logback:logback-classic:1.2.+"
  ...
}
...

Then use this code snippet in Verticle start or other global start method:

// set vertx logger delegate factory to slf4j
String logFactory = System.getProperty("org.vertx.logger-delegate-factory-class-name");
if (logFactory == null) {
    System.setProperty("org.vertx.logger-delegate-factory-class-name", SLF4JLogDelegateFactory.class.getName());
}

Alternatively, you can also set through JVM -D property on command line, e.g.

-Dorg.vertx.logger-delegate-factory-class-name=io.vertx.core.logging.SLF4JLogDelegateFactory

After this, you can use Slf4j to create the logger and start using it.

private static final Logger LOGGER = LoggerFactory.getLogger(MainVerticle.class);
LOGGER.info("starting...");
LOGGER.debug("ouch, something is wrong: {}", ex);
...

Here is a sample logback config file logback.xml that you can put on the classpath, based on the package, it logs either to server log or request log. In part 2, we will cover how to do request logging with Vert.x.

<configuration>

    <!-- for production please use /var/log/xyz directory instead of /tmp/log/xyz -->
    <property name="LOG_FILE" value="/tmp/log/woshiadai/server.log"/>
    <property name="REQUEST_LOG_FILE" value="/tmp/log/woshiadai/request.log"/>

    <!-- console output -->
    <appender class="ch.qos.logback.core.ConsoleAppender" name="STDOUT">
        <encoder>
            <pattern>%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n</pattern>
        </encoder>
    </appender>

    <!-- server log file output -->
    <appender name="SERVER_LOG" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${LOG_FILE}</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
            <fileNamePattern>${LOG_FILE}.%d{yyyy-MM-dd}.%i.gz</fileNamePattern>
            <maxFileSize>200MB</maxFileSize>
            <maxHistory>24</maxHistory>
            <totalSizeCap>5GB</totalSizeCap>
        </rollingPolicy>
        <encoder>
            <pattern>%-4relative [%thread] %-5level %logger{36} - %msg%n</pattern>
        </encoder>
    </appender>
    <appender name="SERVER_LOG_ASYNC" class="ch.qos.logback.classic.AsyncAppender">
        <appender-ref ref="SERVER_LOG" />
        <discardingThreshold>0</discardingThreshold>
        <queueSize>512</queueSize>
        <maxFlushTime>5000</maxFlushTime>
        <neverBlock>true</neverBlock>
    </appender>

    <!-- request log output -->
    <appender name="REQUEST_LOG" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${REQUEST_LOG_FILE}</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
            <fileNamePattern>${REQUEST_LOG_FILE}.%d{yyyy-MM-dd}.%i.gz</fileNamePattern>
            <maxFileSize>50MB</maxFileSize>
            <maxHistory>14</maxHistory>
            <totalSizeCap>5GB</totalSizeCap>
        </rollingPolicy>
        <encoder>
            <pattern>%msg%n</pattern>
        </encoder>
    </appender>
    <appender name="REQUEST_LOG_ASYNC" class="ch.qos.logback.classic.AsyncAppender">
        <appender-ref ref="REQUEST_LOG" />
        <discardingThreshold>0</discardingThreshold>
        <queueSize>5000</queueSize>
        <neverBlock>true</neverBlock>
    </appender>

    <!-- logger for application package -->
    <logger level="INFO" name="io.woshiadai.starter" additivity="false">
        <appender-ref ref="SERVER_LOG_ASYNC"/>
    </logger>

    <!-- logger for RAPS request log -->
    <logger level="INFO" name="io.woshiadai.starter.Slf4jRequestLogger" additivity="false">
        <appender-ref ref="REQUEST_LOG_ASYNC"/>
    </logger>

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

</configuration>

To be continued… see Part 2