Showing posts with label logging. Show all posts
Showing posts with label logging. Show all posts

Monday, September 16, 2024

Spring Code TIP-2: Assert expected log message in a test-case . . .

Logging is helpful to know the insights of a running application. It is also useful in investigating issues. Sometimes, we would like to log certain configuration details after the application starts up. This can be achieved by implementing functional interface CommandLineRunner. Any bean that implements this interface is a special type of bean that runs after the application context is fully loaded.

CommandLineRunner is a functional interface with a single method run(String... args). Beans implementing this interface are executed after the application context is loaded and before the Spring Boot application starts.

For example the following application class defines a CommandLineRunner bean. The bean returns a lambda expression which defines the behavior of the CommandLineRunner. As an altervative to defining a bean, the MyApplication class can also implement this interface and provide implementation for run method. As shown below, this bean checks and if the jdbcClient is available, it executes a SQL query to get the database version and logs the result. This is run after the application context is fully loaded so that we know the version of the Database that the application is using. This is one such very useful information.

@SpringBootApplication @Slf4j public class MyApplication { public static void main(String[] args) { SpringApplication.run(MyApplication.class, args); } @Bean public CommandLineRunner initializationChecks(@Autowired(required = false) JdbcClient jdbcClient) { return args -> { if (jdbcClient != null) { log.info("Database check: {}", jdbcClient.sql("SELECT version()").query(String.class).single()); } }; } }

Now, say we want to assert this log message in a test-case. That way we ensure that the log message contains the expected version of the Database, and the Database won't get changed/upgraded without a test-case catching it.

Spring Code TIP - test log message

JUnit's @ExtendsWith annotation and Spring Boot's OutputCaptureExtension can be leveraged to  achieve this.

The following is an integration test, that does this:
@SpringBootTest(useMainMethod = SpringBootTest.UseMainMethod.ALWAYS) @ExtendWith(OutputCaptureExtension.class) class MyApplicationIntegrationTest { @Autowired ApplicationContext applicationContext; @Autowired MyService myService; @Test @DisplayName("An integration Smoke Test to ensure that the application context loads, autowiring works, and checks DB version.") void smokeTest_context_loads_and_autowiring_works(CapturedOutput output) { var otherService = applicationContext.getBean(OtherService.class); assertThat(otherService).isInstanceOf(OtherService.class); assertThat(myService).isNotNull(); assertThat(output).contains("Database version: PostgreSQL 15.3"); } }

Highlighted is the code in focus, assuming that the Database used is PostgreSQL 15.3.

Wednesday, December 08, 2021

Maven Dependencies Fix - Need to support both Log4j (ver 1) & Log4j2 (ver 2) but exclude Log4j (ver 1) . . .

Software development never gets simple. A simple logging in modern Java applications is not simple enough. There are several logging frameworks: java.util.logging, log4j, log4j2, SLF4J, Logback etc. A typical Java application these days brings in one, or more, or even all of these dependencies. It's often a confusion which one is better, which one to use, which one is in action, which one to configure, and how to configure etc. It becomes worse if you need to exclude any.

I was recently working on a task to fix Security Vulnerabilities detected and reported by a commercial SaaS tool that scans Java project codebase and it's dependent libraries. The tool scans and generates a report listing vulnerabilities detected by categorizing each into Critical/High/Medium/Low. Obviously, when there is an unpatched dependent library marked Critical, that draws superior-attention and brings in a worry with the word: "hacking"- a scary or not-scary word in Software Engineering, it depends ;).

This post is NOT about the messy path that Java logging has been going on right from the beginning. It's about dealing with a need to support both log4j (ver 1) and log4j2 (ver 2) in a Java project but want to exclude log4j from the dependency list to fix the security vulnerability reported in reference to the specific vulnerability reported on log4j in the National Vulnerability Database

To deal with this issue, all you ned to do is exclude log4j from the dependency library that depends on it, and add an explicit dependency of log4j2 and the log4j1-2 bridge.

The following is a snipper of maven pom.xml.
... <properties> <log4j.version>2.15.0</log4j.version> </properties> <dependencies> ... <dependency> <groupId>com.some.lib</groupId> <artifactId>somelib-need-log4j</artifactId> <exclusions> <!-- Fix Security Vulnerability reported with log4j-1.2.17, the last discontinued version of log4j 1. Exclude log4j 1 and depend on the log4j 1 to 2 bridge and bring in log4j 2 explicitly --> <exclusion> <groupId>log4j</groupId> <artifactId>log4j</artifactId> </exclusion> </exclusions> </dependency> <!-- Fix Security Vulnerabily reported with log4j-1.2.17 Log4j 1 to 2 bridge to forward log4j 1 calls to 2 --> <!-- log4j 1 to 2 bridge --> <dependency> <groupId>org.apache.logging.log4j</groupId> <artifactId>log4j-1.2-api</artifactId> <version>${log4j.version}</version> </dependency> <!-- log4j 2 --> <dependency> <groupId>org.apache.logging.log4j</groupId> <artifactId>log4j-api</artifactId> <version>${log4j.version}</version> </dependency> <dependency> <groupId>org.apache.logging.log4j</groupId> <artifactId>log4j-core</artifactId> <version>${log4j.version}</version> </dependency> ... </dependencies> ...

TIP

Leverage maven dependency:tree goal to see which dependency's transitive dependencies bring in the library that needs an attention.

mvn dependency:tree


References

Thursday, October 21, 2021

Spring boot upgrade from 2.2.x to 2.5.x - Spring Cloud Sleuth Zipkin - log message format change . . .

I recently upgraded a Spring Boot micro-service application from Spring Boot 2.2.11 to 2.5.3 and Java OpenJDK 15 to Java Amazon Corretto 16.

Upgrading Java was smooth. Some major and breaking changes that I came across from Spring Boot side include:
  • Profile changes - documented well
  • Dependency changes - Obvious
  • Spring Cloud Sleuth Zipkin - Undocumented glitch
This post is on the Spring Cloud Sleuth Zipkin - undocumented removal of exportable property.

Environment: Java 16, Spring Boot 2.5.3 on macOS Catalina 10.15.7

We have application logs collected, ingested and indexed in Datadog by Logstash scrapping Mesos application's stdout. Soon after the upgrade, logs stopped showing up in Datadog. After some investigation, figured out that the pattern parser failed to parse log string as it was expecting log string format like: [service, trace, span, exportable]. But the format after the upgrade was: [service, trace, span]. Basically, the last exportable property with value true or false was missing. 

The trace, span, exportable are injected into log messages by Spring Cloud Sleuth and Zipkin for distributed tracing via log framework MD5. The documentation of Spring Cloud Sleuth seems not updated with this details. :(

In order to get away with this issue on the Datadog, switching to JSON log message format seemed like a better solution as the JSON is better than strict string pattern matchers. This required an explicit logback definition in resources/logback-spring.xml file (yes, XML is the only way) and a new dependency for JSON logging.

src/main/resources/logback-spring.xml
<?xml version="1.0" encoding="UTF-8"?> <configuration> <include resource="org/springframework/boot/logging/logback/defaults.xml"/> <springProperty scope="context" name="serviceName" source="spring.zipkin.service.name"/> <appender name="console" class="ch.qos.logback.core.ConsoleAppender"> <encoder class="net.logstash.logback.encoder.LoggingEventCompositeJsonEncoder"> <providers> <pattern> <pattern> { "timestamp": "%d{yyyy-MM-dd HH:mm:ss.SSS}", "severity": "%level", "service": "${serviceName:-}", "pid": "${PID:-}", "thread": "%thread", "class": "%logger{40}", "trace": "%X{traceId:-}", "span": "%X{spanId:-}", "parent": "%X{parentId:-}", "exportable": "%X{sampled:-}", "logmessage": "%message" } </pattern> </pattern> <!-- Additional support needed for logging stack trace in JSON message --> <!-- https://github.com/logfellow/logstash-logback-encoder --> <stackTrace> <throwableConverter class="net.logstash.logback.stacktrace.ShortenedThrowableConverter"> <maxDepthPerThrowable>30</maxDepthPerThrowable> <maxLength>4096</maxLength> <shortenedClassNameLength>20</shortenedClassNameLength> <rootCauseFirst>true</rootCauseFirst> </throwableConverter> </stackTrace> </providers> </encoder> </appender> <root level="INFO"> <appender-ref ref="console" /> </root> </configuration>

Maven build file, new dependency for JSON log message: pom.xml
<dependency> <groupId>net.logstash.logback</groupId> <artifactId>logstash-logback-encoder</artifactId> <version>6.6</version> </dependency>

With this a sample JSON exception log messages looks like:

{ "timestamp": "2021-12-22 12:26:26.552", "severity": "ERROR", "service": "my-service-api", "pid": "65623", "thread": "http-nio-8080-exec-6", "class": "c.g.s.e.MyServceImpl", "trace": "529f2d2d7a65dde4", "span": "529f2d2d7a65dde4", "parent": "", "exportable": "", "logmessage": "My Exception log mesage.", "stack_trace": "c.g.s.e.MyException: my exception message\n\tat c.g.s.s.MyServiceImpl.serviceMethodOne(MyServiceImpl.java:210)\n\tat c.g.s.s.MyServiceImpl.serviceMethoTwo(MyServiceImpl.java:280)\n" }

References


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


  •