Logback encoder layout for processing output of org.jboss.netty.handler.logging.LoggingHandler

Question

I am using Play 2.3 to develop an application and has enabled netty log wire using -Dhttp.netty.log.wire=true when starting up the play application. I have also set the level="DEBUG" of the logger org.jboss.netty.handler.logging.LoggingHandler in a custom logger.xml file which I have added to the conf directory of the Play application. Next I wanted to take the log messages from this logger to a file with a rolling policy. For this, I have the following configuration in my logger.xml file.

<configuration>

    <conversionRule conversionWord="coloredLevel" converterClass="play.api.Logger$ColoredLevel" />

    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"> 
        <encoder> 
            <pattern>
                %coloredLevel %logger{15} - %message%n%xException{5}
            </pattern> 
        </encoder> 
    </appender>

    <appender name="ACCESS_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>/Users/bathiyap/Drive/logs/access.log</file>
        <!-- daily rollover with compression -->
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>access-log-%d{yyyy-MM-dd}.gz</fileNamePattern>
            <!-- keep 1 week worth of history -->
            <maxHistory>7</maxHistory>
        </rollingPolicy>
        <encoder>
            <pattern>
                %date{yyyy-MM-dd HH:mm:ss ZZZZ} %message%n
            </pattern>
            <immediateFlush>false</immediateFlush>
        </encoder>
    </appender>

    <!-- additivity=false ensures access log data only goes to the access log -->
    <logger name="org.jboss.netty.handler.logging.LoggingHandler" level="DEBUG" additivity="false">
        <appender-ref ref="ACCESS_FILE"/>
    </logger>

    <logger name="play" level="INFO" /> 
    <logger name="application" level="DEBUG" />

    <root level="ERROR">
        <appender-ref ref="STDOUT"/>
    </root>

</configuration>

As seen from the above configurations all log messages from the org.jboss.netty.handler.logging.LoggingHandler are sent to access.log file while all other log messages are simply written to STDOUT. Everything is working as expected with this configuration and all the HTTP request/response related log messages are getting logged in the access.log file.

But now my problem is, the log messages in the access.log file are too much verbose and the events corresponding to the same request/response goes into multilines. I can understand that this is happening due to the encoder block I have specified in the logger.xml for the rolling file appender as below.

<encoder>
    <pattern>
        %date{yyyy-MM-dd HH:mm:ss ZZZZ} %message%n
    </pattern>
    ...
</encoder>

I have seen in the logback documentation that we can specify a layout class for the encoder as below,

<encoder class="ch.qos.logback.core.encoder.LayoutWrappingEncoder">
    <layout class="some layout class">
        <pattern>
            a pattern definition matching the layout class
        </pattern>
    </layout>
</encoder>

Now the question I have is, are there any standard layout classes in Logback for the logger that I am using which generates the log messages, namely, org.jboss.netty.handler.logging.LoggingHandler?

I want each log event (i.e. HTTP request/response) to nicely compact into a single line in the log file in a format such as give below,

#RemoteIP:Port #LocalIP:Port #DateTimeStamp #ElapsedTime #RequestMethod #RequestURI #StatusCode #BytesSent #UserAgent

Where,

#RemoteIP:Port - Remote IP address and Port

#LocalIP:Port - Local IP address and Port

#DateTimeStamp - Date and Timestamp such as 2015-06-12 00:06:44

#ElapsedTime - The time taken to serve the request such as 0.231

#RequestMethod - Request method such as GET, POST

#RequestURI - Requested URI such as /openapi-rest-web/v1/product/1467866?skuDetail=true

#StatusCode - Response status code such as 200

#BytesSent - Response's content length such as 3167

#UserAgent - Remote user agent such as ""Mozilla/5.0 (Linux; U; Android 4.4.4; Nexus 5 Build/KTU84P)"

Thanks in advance.

Answer 1

We followed that Action.Simple approach to solve the problem. You have call the action in your controller with following annotation @With(LogAction.class)

@Override
  public F.Promise<Result> call(Http.Context ctx) throws Throwable {
  Http.Request request = ctx.request();
  Date curDate = new Date();
  SimpleDateFormat format = new SimpleDateFormat("d/EEE/yyyy HH:mm:ss Z");
  F.Promise<Result> call = delegate.call(ctx);
  return call.map(r -> {

      accessLogger.info(request.remoteAddress() +
              "- ["+format.format(curDate)+"] "+ request.method() +
              " "+ request.uri() + " " + r.status());      

      return r;
  });
}}

Also in the application-logger.xml change the pattern to just the message since we also wanted to format the time.

    <encoder>
        <pattern>%message%n</pattern>
        <!-- this quadruples logging throughput -->
    </encoder>