Wednesday, June 27, 2018

Log exceptions with exceptional details . . .

Logging is generally considered a cross-cutting concern. So as logging exceptions is. An appropriate level of details added to exception log is always very helpful and gives a jump-start in investigating the root cause of an exception.

Grails provides good exception logging, filters out unnecessary stack traces (configurable by setting grails.full.stacktrace property) by default, that otherwise would be too long. It also provides configurable way of adding additional details to the exception log message. Additional details like request parameters can be added to exception log message (by setting the property  grails.exceptionresolver.logRequestParameters = true in Config.groovy) which is by default enabled in only development env). Also, certain sensible request parameters and values can be masked from exception logging by setting an additional property grails.exceptionresolver.params.exclude = ['password']).

In a Web or RESTful API application, request parameters added to exception log message cover all http methods like GET that send parameters as part of the query string. However, http methods like POST typically send parameters in the request body, but not in the query string. Logging request body along with exception message is as useful as logging request parameters. Grails doesn't provide a configurable way of adding this level of details to exception log message. But this can easily be added with minimal coding, configuration and by leveraging the underlying Spring framework.

Environment: Grails 2.5.4, Java 8 on MacOS High Sierra 10.13.5

Imagine, a Grails application providing various RESTful end-points that take JSON payload as the body in POST requests. If some exception arises while processing a request, an exception log that includes request payload received will be very helpful to investigate the root cause. This requires accessing the original http request body in an exception resolver at the time when the exception is raised. Grails default exception resolver class is: GrailsExceptionResolver. This class is extendable. All we need to do is override one of it's methods that forms the exception log message.

Extend GrailsExceptionResolver and override getRequestLogMessage(Throwable e, HttpServletRequest request). This method already has HttpServletRequest parameter. So, getting access to request body is possible, but it is not available. The problem is, by this time, the request body must have already been read either by calling getInputStream() or getReader() method in order to consume and process the JSON payload. Once read, it's not available anymore and subsequent reads only result in an exception: IllegalStateException. The only way to deal with this limitation is to wrap the original HttpServletRequest into a wrapper HttpServletRequestWrapper, cache it and pass it along the filter chain by making cached request available for multi-reads.

This is bit low-level to dive into in a Grails application. Grails 2 offers a high-level Filters support but it has limitations to use in this solution. So, we have to dive little deeper and put a solution by introducing a Servlet filter that caches and wraps the original request to make it available for multi-reads. But, remember Grails underpins Spring framework. So, it's always a layer to look into for customizations like this and see if there is anything readily available for adopting. In this case, there is a filter org.springframework.web.filter.CommonsRequestLoggingFilter which wraps the request into  org.springframework.web.util.ContentCachingRequestWrapper and is just appropriate for this solution to leverage.

Now, we have all pieces of the puzzle. Let's put these together into a solution.

Step-1

Extend GrailsExceptionResolver and overwrite getRequestLogMessage(Throwable e, HttpServletRequest request)method. The following is an example of extended exception resolver:
src/groovy/grails/logging/LogRequestBodyExceptionResolver.groovy
package com.giri.grails.logging import com.giri.grails.web.RequestCacheFilterUtil import org.codehaus.groovy.grails.web.errors.GrailsExceptionResolver import org.springframework.http.HttpMethod import org.springframework.http.MediaType import javax.servlet.http.HttpServletRequest /** * Exception resolver, adds request body to exception log message by getting it from the request body cached by * {@link org.springframework.web.util.ContentCachingRequestWrapper} * * @see {@link org.springframework.web.util.ContentCachingRequestWrapper} * @see /src/templates/war/web.xml * @see /conf/spring/resources.groovy * * @author gpottepalem * Created on Jun 27, 2018 */ class LogRequestBodyExceptionResolver extends GrailsExceptionResolver { static final List LOG_PAYLOAD_FOR_HTTP_METHODS = [HttpMethod.POST, HttpMethod.PUT]*.name() static final List LOG_PAYLOAD_FOR_HTTP_CONTENT_TYPES = [MediaType.APPLICATION_JSON_VALUE] /** * Enhances Grails log message for logging exceptions by adding the original request payload to the exception * message * @param e the exception * @param request request * @return enhanced log message that includes request payload (body) */ @Override String getRequestLogMessage(Throwable e, HttpServletRequest request) { String logMessage = super.getRequestLogMessage(e, request) String payload = RequestCacheFilterUtil.getCachedRequestPayload(request) if (request.method in LOG_PAYLOAD_FOR_HTTP_METHODS && request.contentType in LOG_PAYLOAD_FOR_HTTP_CONTENT_TYPES) { logMessage += "\n${request.method} ${request.contentType} payload: ${payload}\n" } return logMessage } }

Here is the utility class that the above code snippet uses:
src/groovy/grails/web/RequestCacheFilterUtil.groovy
package com.giri.grails.web import org.springframework.web.util.ContentCachingRequestWrapper import org.springframework.web.util.WebUtils import javax.servlet.http.HttpServletRequest /** * Utility class. Provide methods for working on the cached request payload. The original request once per * request is cached by {@link ContentCachingRequestWrapper} in the filter * {@link org.springframework.web.filter.CommonsRequestLoggingFilter} setup in web.xml * * @see /src/templates/war/web.xml * * @author gpottepalem * Created on Jun 27, 2018 */ class RequestCacheFilterUtil { /** * Utility method to get payload of the cached request. * * @param request the request * @return payload as String * @throws UnsupportedEncodingException */ static String getCachedRequestPayload(final HttpServletRequest request) throws UnsupportedEncodingException { String payload ContentCachingRequestWrapper wrapper = WebUtils.getNativeRequest(request, ContentCachingRequestWrapper.class) if (wrapper) { byte[] buffer = wrapper.getContentAsByteArray() if (buffer) { payload = new String(buf, 0, buf.length, wrapper.getCharacterEncoding()) } } return payload } }

Once we have extended Grails provided GrailsExceptionResolver class as shown above, we need to override Grails provided exception resolver and register this as our application's exception handler. A bean definition in resources.groovy like the following will exactly do that:
grails-app/conf/spring/resources.goovy
beans = { ... // custom exception handler to log request body in addition to log message for exceptions exceptionHandler(LogRequestBodyExceptionResolver) { exceptionMappings = [ 'java.lang.Exception': '/error' ] } }

That is one side of this problem which takes care of logging request body along with the exception message for exceptions.

Step-2

The other side of the problem is to put a solution to make request body available for multiple reads. Typically once getInputStream() or getReader() is called to consume request body from  HttpServletRequest the next call will throw an exception preventing it to call multiple times. This needs a way to cache the request and wrap it using HttpServletRequestWrapper to make it's body readable multiple times. Fortunately Spring comes with ContentCachingRequestWrapper that exactly does this. But this needs to be done in a filter to wrap the request. Grails filters will not let this level of customization with request or response objects available in filters. This needs a servlet filter configuration. Spring comes with few handy implementations of filters that use ContentCachingRequestWrapper in them. One such useful filter class is: CommonsRequestLoggingFilter that allows request customizations. This filter can be setup in web.xml as a servlet filter that in-turn caches and wraps HttpServletRequest.

A typical Grails application doesn't include web.xml as it gets created when the application war file is built. In order to get this filter definition into the generated web.xml that gets bundled into war file, we need to install Grails templates. These are the templates that Grails framework uses for code generations. For customizing any code generation, we need to install and make changes to the corresponding template, in this case templates/war/web.xml file is the one we add a filter into.

Running the command: grails install-templates, installs all templates that Grails framework itself uses to generate code under src/templates dir. For this solution, we don't need all installed template files. We can delete all except web/web.xml once templates.

Edit war/web.xml and add the following filter entry:
... <!-- ================ Custom filters BEGIN ================ --> <!-- Filter provides org.springframework.web.util.ContentCachingRequestWrapper which in turn caches and makes request body multi-readable. We leverage the cached request and access request body in LogRequestBodyExceptionResolver for logging enhanced exception message that includes request payload. --> <filter> <filter-name>commonsRequestLoggingFilter</filter-name> <filter-class>org.springframework.web.filter.CommonsRequestLoggingFilter</filter-class> <init-param> <param-name>includePayload</param-name> <param-value>true</param-value> </init-param> <init-param> <param-name>includeClientInfo</param-name> <param-value>true</param-value> </init-param> <init-param> <param-name>includeQueryString</param-name> <param-value>true</param-value> </init-param> </filter> <!-- URL patterns the filter is applied to --> <filter-mapping> <filter-name>commonsRequestLoggingFilter</filter-name> <url-pattern>/sites/*</url-pattern> <url-pattern>/api/*</url-pattern> <url-pattern>/admin/*</url-pattern> </filter-mapping> <!-- ================ Custom Filters END ================= --> ...

This makes every request go through this filter for listed URL patterns.

With this, we have enhanced Grails provided exception resolver that adds request body to exception log message which gets logged when an exception arises while processing a http request that includes body.

TIP

As this solution leverages Spring provided request logging filter that offers logging request parameters, body and client-info of every request for debug level when enabled, we can as well have debug log level enabled for this class in development in Config.groovy:

log4j = { environments { development { ... debug 'org.springframework.web.filter.CommonsRequestLoggingFilter' ... } } }

This will log every request that goes through this filter with extra enabled details in debug mode.

References


  • Grails Filters Doc
  • Grails install-templates command
  • Grails Goodness: Exception Methods in Controllers
  • Logging http request and response with Spring 4


  • No comments:

    Post a Comment