[2.3.8-java] access logging with Play-Authenticate in three easy steps

[Slim Slam]

Here's one solution for access logging using Play-Authenticate (joscha.github.io/play-authenticate).

The only thing I'd like to add is the HTTP status code (e.g. 404 for file not found, 200 for success, etc). 

Any suggestions are welcome.

1. Create a logging actions file, I'll call it  app/actions/AddUserToAccessLog.java

The contents are here:

package actions;

import java.util.Date;
import models.User;
import controllers.Application;

import play.Logger;
import play.Logger.ALogger;

import play.libs.F;
import play.mvc.Action;
import play.mvc.Http;
import play.mvc.Result;
   
public class AddUserToAccessLog extends Action.Simple {

 private final ALogger accessLogger = Logger.of("access");
 String usern = "nouser";
   
 @Override
 public F.Promise<Result> call(Http.Context context) throws Throwable {
 Http.Session session = context.session();
 Http.Request request = context.request();
 Http.Response response = context.response();
 
 // Size of payload
 String size = request.getHeader("Content-Length");
 if (size == null) {
  size = "0";
 }
 
 // Get users email address from play-authenticate
 User user = Application.getLocalUser(context.session());
 if (user != null) {
  usern = user.email;
 }
   
 // Generate Common Log Format timestamp
 String timestamp = new java.text.SimpleDateFormat("MM/dd/yyyy:H:mm:ss Z").format(new Date());
 
 // Exchange HTTP for HTTPS if its an SSL connection - just for kicks
 String version = request.version();
 Boolean ssl = request.secure();
 if (ssl) {
  version = version.replace("HTTP", "HTTPS");
 }
 
// Apache Common Log Format entry
 accessLogger.info(request.remoteAddress() + " - " + usern + " [" + timestamp + "] \"" + request.method() + " " + request.uri() + " " + version + "\" - " + size);
 
 return delegate.call(context);
 }
}

2. Your conf/application-logger.xml file needs to have the name of the access logger in it  (here named "access")

<configuration>


    <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>${application.home}/logs/application.log</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <!-- Daily rollover with compression -->
          <fileNamePattern>${application.home}/logs/application-log-%d{yyyy-MM-dd}.gz</fileNamePattern>
            <!-- keep 30 days worth of history -->
            <maxHistory>30</maxHistory>
        </rollingPolicy>
        <encoder>
            <pattern>%date{yyyy-MM-dd HH:mm:ss ZZZZ} [%level] from %logger in %thread - %message%n%xException</pattern>
        </encoder>
    </appender>


    <appender name="ACCESS_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>${application.home}/logs/access.log</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <!-- daily rollover with compression -->
            <fileNamePattern>${application.home}/logs/access-log-%d{yyyy-MM-dd}.gz</fileNamePattern>
            <!-- keep 30 days worth of history -->
            <maxHistory>30</maxHistory>
        </rollingPolicy>
        <encoder>
            <pattern>%message%n</pattern>
            <!-- this quadruples logging throughput -->
            <!-- immediateFlush>false</immediateFlush -->
        </encoder>
    </appender>


    <!-- additivity=false ensures access log data only goes to the access log -->
    <logger name="access" level="INFO" additivity="false">
        <appender-ref ref="ACCESS_FILE" />
    </logger>


    <root level="INFO">
        <appender-ref ref="FILE"/>
    </root>


</configuration>

3.  Any Controllers that you want to intercept (probably all of them), need to have an @With line added like this:

import play.mvc.With;
import actions.AddUserToAccessLog;


@With({AddUserToAccessLog.class})
public class MyFunController extends Controller {
  ...........
}

That's it.  Any suggestions on how to add the HTTP status code to the access log are appreciated.

J

[Slim Slam]

Anyone have a suggestion on how to add the HTTP status code to my code? It seems that

I'm possibly intercepting the access attempt before the HTTP status code is generated (?)

J

[Igmar Palsenberg]

Op woensdag 25 maart 2015 19:01:48 UTC+1 schreef Slim Slam:

Anyone have a suggestion on how to add the HTTP status code to my code? It seems that

I'm possibly intercepting the access attempt before the HTTP status code is generated (?)

I don't think you can : You intercept before the controller is entered. The code itself is generated in the controller itself. 

Igmar

[Slim Slam]

Well, surely it's possible to implement access logging that includes the HTTP status code.

What would I need to change in order to do that?  Or what approach would I need to take?

J

[Craig O]

Something like this should work.  

        return delegate.call(ctx).map(result -> log(ctx,result));

But it won't handle exceptions.  This should handle that (you need to re-throw in the exception handler)

        return delegate.call(ctx).map(result -> log(ctx,result)).recover((throwable) -> logError(throwable, ctx));

Be interested to know if you get it working!

[Slim Slam]

Hi Craig,

    Thanks for the suggestion. Is this "return" call modification that you're suggesting the

"return" call of the AddUserToAccessLog.java action that I posted above?  If so, how would I

capture the HTTP status code for my access log entries? It's not clear to me from your

suggestion.

Thanks,

J

[Slim Slam]

Is this line:

 return delegate.call(ctx).map(result -> log(ctx,result));

supposed to go at the end of the action?  In any case, this "map(result -> log(ctx,result)" does

not appear to be a legal expression in Java.

J

[Craig O]

Hi J,

Sorry for the delay.

That is legal Java 8.  It's a Lambda expression.  If you are using Java Play, you really want to be using Java 8, it's a much nicer fit with Play.

The map method will call your log method when the Promise of the Result is redeemed.  Inside your log method, you should be able to call this :-

result.toScala().header().status()

It doesn't go at the end of the action, it's just added to the end of the delegate.call(ctx).  The log method will be called asynchronously.

Hope this makes enough sense for you to use, let me know if it works.

Craig

[Slim Slam]

Hi Craig,

   Thanks for the response. Ok, that makes sense. However, we are currently stuck on Java 7 because of a dependency in

a couple of critical libraries we use with Play.  So, I guess that's a no-go for now.  Any workaround for Java 7?

Cheers,

J

[Craig O]

This should work for you (IDEA can convert between lambdas and anonymous inner classes)

return delegate.call(ctx).map(new F.Function<Result, Result>()
{
    @Override
    public Result apply(Result result) throws Throwable
    {
        return log(ctx, result);
    }
});

[Slim Slam]

Hi Craig,

  Neither the method "log" nor the object "ctx" appear to be available from

within this inner class. Is there some definitions missing?

J

[Craig O]

You have to define the log method yourself, perhaps calling YourClass.this.log

Also, you should use context instead of ctx (as that is what your parameter is called).

This is your code from above.

 public F.Promise<Result> call(Http.Context context) throws Throwable {

[Slim Slam]

Hi Craig, 

So, the return replaces the return delegate.call(context) at the end of the action like this (?)

@Override

 public F.Promise<Result> call(Http.Context context) throws Throwable {

...
...
...
...
 return delegate.call(ccontext).map(new F.Function<Result, Result>() {

 
 @Override
 public Result apply(Result result) throws Throwable
 {

 return log(context, result);
 }
});

}