Custom Logging Filter – Jersey ContainerRequestFilter & ContainerResponseFilter

By | November 7, 2015

What we have in this post?

  • RESTFul Web Service using Jersey Framework.
  • Create custom request and response filter
    • Request filter will intercepts the requests coming to RESTFul web service
    • Response filter will intercepts the response generated by RESTFul web service.
  • Create Application level exception mapper to catch all application exceptions.
  • Generate Logger framework to generate logs.

Logging background & related applications:

Logging is primary requirement for most of web service application. Most of the time, we have a requirement of keeping it as cross cutting concern i.e. typically we want to keep the logging at one place, we do not want to mix the logging with application code.

We have already discussed about Logging of RESTFul Web Service using Spring AOP. In this post, we will achieve the logging of RESTful web service using filters of jersey framework. The application logs will be generated in custom Jersey filter. In our discussion we will create a resource and will write filters to intercept the requests directed REST resource. Also, we will write our ExceptionMapper class to catch application level exceptions. We have used log4j logger libraries to log the requests and responses. We have discussed about the basics of filter in what is filter in enterprise applications.

Custom Logging filter using Jersey framework:

We will implement custom logging filter using ContainerRequestFilter and ContainerResponseFilter.  The custom logging filter will implements ContainerRequestFilter  and ContainerResponseFilter. The class hierarchy is as shown in Fig 1.

  • CustomLoggingFilter will intercepts Request coming to Service
  • CustomLoggingFilter will intercepts the response (while sending response back to Client)
Jersey request response filter
Fig 1: Class Hierarchy of our CustomLoggingFilter

We will be concerned about implementing the following functions


public void filter(ContainerRequestContext requestContext) throws IOException;
public void filter(ContainerRequestContext requestContext, ContainerResponseContext 
responseContext) throws IOException;

The first method deals with intercepting the requests coming to service and second method is responsible for intercepting the response. To calculate the execution of request we are using MDC (mapped diagnostic context). When requests arrived in service we note down the time of request and while sending the response we will again note down the time. The difference will give us the execution time of method. These kind of features are useful for Audit trialing, Trouble shooting, analysis and profiling of web services.

In CustomLoggingFilter apart from above functions we have following main functions, who are responsible for parsing the incoming request.
logQueryParameters : This function will read the query parameters coming in the HTTP Request and log the parameters.
logMethodAnnotations: This function logs annotations of resource. Generally resource have @GET or @POST or @Produces or @Consumes or @Path annotations, So this method will log all the annotation which the requested resource have.
logRequestHeader: This function read all the headers parameters which HTTP request have and logs the request parameters.
readEntityStream : This function will read the entity stream like in the POST request and log it. We have log this in case of POST request coming to function.

Custom logging filter class – request & response

package org.learn;

import java.io.ByteArrayInputStream;
import java.io.ByteArrayOutputStream;
import java.io.IOException;
import java.io.InputStream;
import java.lang.annotation.Annotation;
import java.util.Iterator;
import java.util.List;

import javax.ws.rs.container.ContainerRequestContext;
import javax.ws.rs.container.ContainerRequestFilter;
import javax.ws.rs.container.ContainerResponseContext;
import javax.ws.rs.container.ContainerResponseFilter;
import javax.ws.rs.container.ResourceInfo;
import javax.ws.rs.core.Context;
import javax.ws.rs.ext.Provider;

import org.glassfish.jersey.message.internal.ReaderWriter;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;

@Provider
public class CustomLoggingFilter implements ContainerRequestFilter, ContainerResponseFilter {
    @Context
    private ResourceInfo resourceInfo;

    private static final Logger log = LoggerFactory.getLogger(CustomLoggingFilter.class);

    @Override
    public void filter(ContainerRequestContext requestContext) throws IOException {
        //Note down the start request time...we will use to calculate the total
        //execution time
        MDC.put("start-time", String.valueOf(System.currentTimeMillis()));

        log.debug("Entering in Resource : /{} ", requestContext.getUriInfo().getPath());
        log.debug("Method Name : {} ", resourceInfo.getResourceMethod().getName());
        log.debug("Class : {} ", resourceInfo.getResourceClass().getCanonicalName());
        logQueryParameters(requestContext);
        logMethodAnnotations();
        logRequestHeader(requestContext);

        //log entity stream...
        String entity = readEntityStream(requestContext);
        if(null != entity && entity.trim().length() > 0) {
            log.debug("Entity Stream : {}",entity);
        }
    }

	private void logQueryParameters(ContainerRequestContext requestContext) {
        Iterator iterator = requestContext.getUriInfo().getPathParameters().keySet().iterator();
        while (iterator.hasNext()) {
            String name = iterator.next();
            List obj = requestContext.getUriInfo().getPathParameters().get(name);
            String value = null;
            if(null != obj && obj.size() > 0) {
                value = obj.get(0);
            }
            log.debug("Query Parameter Name: {}, Value :{}", name, value);
        }
    }

    private void logMethodAnnotations() {
        Annotation[] annotations = resourceInfo.getResourceMethod().getDeclaredAnnotations();
        if (annotations != null && annotations.length > 0) {
            log.debug("----Start Annotations of resource ----");
            for (Annotation annotation : annotations) {
                log.debug(annotation.toString());
            }
            log.debug("----End Annotations of resource----");
        }
    }

    private void logRequestHeader(ContainerRequestContext requestContext) {
        Iterator iterator;
        log.debug("----Start Header Section of request ----");
        log.debug("Method Type : {}", requestContext.getMethod());
        iterator = requestContext.getHeaders().keySet().iterator();
        while (iterator.hasNext()) {
            String headerName = iterator.next();
            String headerValue = requestContext.getHeaderString(headerName);
            log.debug("Header Name: {}, Header Value :{} ",headerName, headerValue);
        }
        log.debug("----End Header Section of request ----");
    }

    private String readEntityStream(ContainerRequestContext requestContext)
    {
        ByteArrayOutputStream outStream = new ByteArrayOutputStream();
        final InputStream inputStream = requestContext.getEntityStream();
        final StringBuilder builder = new StringBuilder();
        try
        {
            ReaderWriter.writeTo(inputStream, outStream);
            byte[] requestEntity = outStream.toByteArray();
            if (requestEntity.length == 0) {
                builder.append("");
            } else {
                builder.append(new String(requestEntity));
            }
            requestContext.setEntityStream(new ByteArrayInputStream(requestEntity) );
        } catch (IOException ex) {
            log.debug("----Exception occurred while reading entity stream :{}",ex.getMessage());
        }
        return builder.toString();
    }

    @Override
    public void filter(ContainerRequestContext requestContext, ContainerResponseContext responseContext)
                                 throws IOException {
        String stTime = MDC.get("start-time");
        if(null == stTime || stTime.length() == 0) {
        	return;
        }
    	long startTime = Long.parseLong(stTime);
        long executionTime = System.currentTimeMillis() - startTime;
        log.debug("Total request execution time : {} milliseconds",executionTime);
        //clear the context on exit
        MDC.clear();
    }
}

Model Class of Web Service:

EmployeeModel class is used in resource class of application. We are sending this model class in the form of json or xml to our clients.  Similarly client can post json of employee, we accept the employee json in EmployeeModel. Sooner we will take a look into the resource code.

package org.learn;

import javax.xml.bind.annotation.XmlRootElement;

@XmlRootElement (name = "Employee")
public class EmployeeModel {
    public String name;
    public int age;
    public EmployeeModel() {} // JAXB needs this
 
    public EmployeeModel(String name, int age) {
        this.name = name;
        this.age = age;
    }
}

Jersey REST Service exposing GET & POST resources

ServiceResource: The resource class exposing our REST interfaces. The code of ServiceResource is as follows.

package org.learn;

import java.util.Date;
import java.util.Random;
import java.util.UUID;

import javax.ws.rs.Consumes;
import javax.ws.rs.GET;
import javax.ws.rs.POST;
import javax.ws.rs.Path;
import javax.ws.rs.PathParam;
import javax.ws.rs.Produces;
import javax.ws.rs.core.MediaType;
import javax.ws.rs.core.Response;


@Path("/service")
public class ServiceResource {

	private static final String text = "Message from Server :%s ";

	@GET
	@Consumes(MediaType.TEXT_PLAIN)
	public Response getText() {
		String response = String.format(text, new Date());
		return Response.status(Response.Status.OK).entity(response).type(MediaType.TEXT_PLAIN).build();
	}

	@GET
	@Path("{name}")
	@Consumes(MediaType.TEXT_PLAIN)
	public Response getMsg(@PathParam("name") String name) {
		String response = String.format(text, name);
		return Response.status(Response.Status.OK).entity(response).type(MediaType.TEXT_PLAIN).build();
	}

	@GET
	@Path("/json")
	@Produces(MediaType.APPLICATION_JSON)
	public EmployeeModel getJson() {

		//...........db operation..
		//suppose we get these value from database
		//............
		String randomName = "random" + UUID.randomUUID().toString().substring(0,4);
		int randomAge = new Random().nextInt(100);

		//returns the value received from database
		return new EmployeeModel(randomName,randomAge);
		//return new EmployeeModel("Tom", 21);
	}

	@GET
	@Path("/xml")
	@Produces(MediaType.APPLICATION_XML)
	public EmployeeModel getXml() {

		//...........db operation..
		//suppose we get these value from database
		//............
		String randomName = "random" + UUID.randomUUID().toString().substring(0,4);
		int randomAge = new Random().nextInt(100);

		//returns the value received from database
		return new EmployeeModel(randomName,randomAge);
		//return new EmployeeModel("Tom", 21);
	}

	@POST
	@Path("/json/object")
	@Consumes(MediaType.APPLICATION_JSON)
	@Produces(MediaType.APPLICATION_XML)
	public EmployeeModel postEmployee(EmployeeModel employee) {
		//We receive the object from client
		//Client might have send the json string as {"name":"hello","age":"24"}
		//do some processing ..save in database
		//return the output in xml format....
		return employee;
	}

	@POST
	@Path("/json/{name}")
	@Produces(MediaType.TEXT_PLAIN)
	public Response postPathParamValue(@PathParam("name") String name) {
		//Return what ever received from client
		String output = "Jersey Says :" + name;
		return Response.status(200).entity(output).build();
	}

	@GET
	@Path("/exception")
	@Produces(MediaType.TEXT_PLAIN)
	public Response throwException() {
		throw new RuntimeException("Exception thrown by getPathParamValue resource");
	}
}

Jersey logging filter output – request & response

We will demonstrate the execution of one GET request and corresponding logs which are getting generated.
We have deployed our application at root context running at 9090 port. So our base application url is “http://localhost:9090/”.
GET Request with http://localhost:9090/service will return the output in text format like
Message from Server :Fri Nov 06 15:15:42 IST 2015
The some of logs will be generated for GET request(for complete logs run the application) :


DEBUG   2015-11-06 15:18:41,239 org.learn.CustomLoggingFilter   [http-apr-9090-exec-6]  Entering in Resource : /service
DEBUG   2015-11-06 15:18:41,241 org.learn.CustomLoggingFilter   [http-apr-9090-exec-6]  Method Name : getText
DEBUG   2015-11-06 15:18:41,241 org.learn.CustomLoggingFilter   [http-apr-9090-exec-6]  Class : org.learn.ServiceResource
DEBUG   2015-11-06 15:18:41,241 org.learn.CustomLoggingFilter   [http-apr-9090-exec-6]  ----Start Annotations of resource ----
DEBUG   2015-11-06 15:18:41,241 org.learn.CustomLoggingFilter   [http-apr-9090-exec-6]  @javax.ws.rs.GET()

DEBUG   2015-11-06 15:18:41,241 org.learn.CustomLoggingFilter   [http-apr-9090-exec-6]  ----End Annotations of resource----
DEBUG   2015-11-06 15:18:41,241 org.learn.CustomLoggingFilter   [http-apr-9090-exec-6]  ----Start Header Section of request ----
DEBUG   2015-11-06 15:18:41,241 org.learn.CustomLoggingFilter   [http-apr-9090-exec-6]  Method Type : GET
DEBUG   2015-11-06 15:18:41,241 org.learn.CustomLoggingFilter   [http-apr-9090-exec-6]  Header Name: host, Header Value :localhost:9090
DEBUG   2015-11-06 15:18:41,241 org.learn.CustomLoggingFilter   [http-apr-9090-exec-6]  Header Name: connection, Header Value :keep-alive
DEBUG   2015-11-06 15:18:41,242 org.learn.CustomLoggingFilter   [http-apr-9090-exec-6]  Header Name: cache-control, Header Value :max-age=0
DEBUG   2015-11-06 15:18:41,242 org.learn.CustomLoggingFilter   [http-apr-9090-exec-6]  ----End Header Section of request ----
DEBUG   2015-11-06 15:18:41,242 org.learn.CustomLoggingFilter   [http-apr-9090-exec-6]  Total request execution time : 3 milliseconds

Please refer to below link to download the complete code of Jersey logging project. Once, we download the project zip file there we will find ReadMe.md file, which describe the detail of each resource call and logs generated in that particular call.

Download code – Jersey custom request response filter logging