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.
src/groovy/grails/logging/LogRequestBodyExceptionResolver.groovy
Here is the utility class that the above code snippet uses:
src/groovy/grails/web/RequestCacheFilterUtil.groovy
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
That is one side of this problem which takes care of logging request body along with the exception message for exceptions.
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:
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.
This will log every request that goes through this filter with extra enabled details in debug mode.
Grails Filters Doc
Grails install-templates command
Grails Goodness: Exception Methods in Controllers
Logging http request and response with Spring 4
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.
Posts
No comments:
Post a Comment