Logging and Monitoring in Spring-Boot

Introduction

What is the need for Logging and Monitoring? The response varies depending on who we ask this question, A newbie developer might brush it away as a waste of time, while a middle-level Engineer would agree that it is needed only when we need to debug an issue, whereas seasoned Engineer values Logging and Monitoring to be a most important aspect of an Application. Software’s are assets of a company just like Machines in a Factory. We have to constantly monitor the apps for performance degradation and fine-tune them over time, Logging and Monitoring are the security cameras which help us to see the inner details of the application, and resulting save precious dollars.

Implementation Options?

There are various libraries and options available for implementing Logging and Monitoring. In this blog, I’ll comprehensively look into how we can use these tools, and finally have a robust system of monitoring.

• Log4j2/ Log4j/ SLF4J/ java.util.logging : Different Loggers
• Splunk/ Kibana :- Enhanced Visual representation of Logging
• StatsD :- Metrics aggregator
• Graphite/ influxDB : Metrics recorder
• DataDog/ Grafana : Beutiful Metrics view, alarms
• Micrometer : Vendor independent Interface to communicate with

Log4j2

log4j2 is a tool to help the programmer output log statements to a variety of output targets. In case of issues with applications, then logs would help us to solve and identify problems. To enable log4j2, we need to do the following things.

Step – 1 – Add log4j2 dependency

Add the dependency for log4j2, ignore default logging from logback by ignoring it in starter-web.

<dependency>
	<groupId>org.springframework.boot</groupId>
	<artifactId>spring-boot-starter-web</artifactId>
	<exclusions>
		<exclusion>
			<groupId>org.springframework.boot</groupId>
			<artifactId>spring-boot-starter-logging</artifactId>
		</exclusion>
	</exclusions>
</dependency>
<dependency>
	<groupId>org.springframework.boot</groupId>
	<artifactId>spring-boot-starter-log4j2</artifactId>
</dependency>
<!-- For Async Appender -->
<dependency>
	<groupId>com.lmax</groupId>
	<artifactId>disruptor</artifactId>
	<version>3.3.4</version>
</dependency>

Step – 2 – Add log4j2.xml in resources file

Add log4j2.xml/log4j2.properties/log4j2.yaml in src/main/resources folder. We have added a Rolling File which would create files when filesize>= 10MB. Furthermore, we have added an Async appender for better performance.

<?xml version="1.0" encoding="UTF-8"?>
<Configuration>
	<Properties>
		<Property name="LOG_PATTERN">%d{yyyy-MM-dd HH:mm:ss.SSS},
			message=[%m],traceId=%X{TraceId} %n</Property>
	</Properties>
	<Appenders>
		<Console name="Console" target="SYSTEM_OUT">
			<PatternLayout pattern="${LOG_PATTERN}" />
		</Console>
		<RollingFile name="File" fileName="/..file/logs/log4j2.log"
			filePattern="/..file/logs/log4j2-%d{yyyy-MM-dd}-%i.log">
			<PatternLayout pattern="${LOG_PATTERN}" />
			<Policies>
				<SizeBasedTriggeringPolicy size="10MB" />
			</Policies>
			<DefaultRolloverStrategy max="10" />
		</RollingFile>
	</Appenders>
	<Loggers>
		<Logger name="com.jones.shoppingmart.ProductSerice"
			level="TRACE">
			<AppenderRef ref="Console" />
		</Logger>
		<AsyncRoot level="INFO">
			<AppenderRef ref="Console" />
			<AppenderRef ref="File" />
		</AsyncRoot>
	</Loggers>

</Configuration>

Output

AOP – Based Logging + EventBus

One of the central tenets of the Spring Framework is that of non-invasiveness. This is the idea that you should not be forced to introduce framework-specific classes and interfaces into your business or domain model, hence to utilize the non-invasive approach, we would be implementing Logging via Spring AOP. Further, each Controller needs logging, which is a cross-cutting concern in our App, so our solution should be able to accommodate all controllers easily.

AOP Proxies: The key thing to understand here is that when we Autowire Objects, we get a reference to the proxy. This means that method calls on that object reference are calls on the proxy. As a result, the proxy can delegate to all of the interceptors (advice) that are relevant to that particular method call. However, once the call has finally reached the target object any method calls are going to be invoked against the reference, and not the proxy. Read More

Let us look into some central AOP concepts and terminology, and see that in a class

• Aspect : A modularization of a concern that cuts across multiple classes. Transaction management is a good example of a crosscutting concern in enterprise Java applications. 
• Join point : A point during the execution of a program, such as the execution of a method.
• Advice : Action taken by an aspect at a particular join point, Ex of advice are “around”, “before” and “after”.
• Pointcut : A predicate that matches join points.

Step – 1 – Add AOP + EventBus dependency

Add dependency of AOP, and actuator

		<dependency>
			<groupId>org.springframework.boot</groupId>
			<artifactId>spring-boot-starter-aop</artifactId>
		</dependency>
		<dependency>
			<groupId>org.springframework.boot</groupId>
			<artifactId>spring-boot-starter-actuator</artifactId>
		</dependency>
		<dependency>
			<groupId>org.projectlombok</groupId>
			<artifactId>lombok</artifactId>
			<scope>provided</scope>
		</dependency>
        <!-- For Event Bus -->
		<dependency>
			<groupId>com.google.guava</groupId>
			<artifactId>guava</artifactId>
			<version>29.0-jre</version>
		</dependency>

Step – 2 – Create a LoggingEntity Class

@Getter
@Builder
public class LoggingEntity {
	 	
	
	@Builder.Default
	private String message = "";
	@Builder.Default
	private String method = "";
	@Builder.Default
	private Status status = Status.NA;
	@Builder.Default
	private Level level = Level.NA;
	
	public static enum Status {
		SUCCESS, FAILURE, NA;
	}
	
	public static enum Level {
		DEBUG, INFO, WARN, ERROR, NA;
	}

}

Step – 3 – Write the Aspect Class

Around Advice helps us to log all requests that come to ProductController, and we are using an EventBus to publish loggable information in LoggingEntity.

package com.jones.shoppingmart.monitoring;

@Aspect
@Component
public class ShoppingMonitor {
	
	private static final String POINTCUTS = "productApis()";
	private EventBus eventBus;
	
	@Autowired
	public ShoppingMonitor(EventBus eventBus) {
		this.eventBus = eventBus;
	}
	
	@Pointcut("execution(* com.jones.shoppingmart.controller.ProductController.*(..))")
	public void productApis() {
	}
	
	@Around(POINTCUTS)
	public Object recordApi(ProceedingJoinPoint proceedingJoinPoint) throws Throwable {
		
		HttpServletRequest request = ((ServletRequestAttributes)RequestContextHolder
				.currentRequestAttributes()).getRequest();
		String method = proceedingJoinPoint.getSignature().getName();
		String className = proceedingJoinPoint.getSignature().getDeclaringType().getSimpleName();
		Object response = null;
		try {
			response = proceedingJoinPoint.proceed();
			LoggingEntity loggingEntity = LoggingEntity.builder().message("Product service call is success for Api" + request.getRequestURI().toString())
					.level(LoggingEntity.Level.INFO).status(LoggingEntity.Status.SUCCESS).method(className + "." + method).build();
			eventBus.post(loggingEntity);
		} catch (Exception e) {
			LoggingEntity loggingEntity = LoggingEntity.builder().message("Service call is success" + request)
					.level(LoggingEntity.Level.ERROR).status(LoggingEntity.Status.FAILURE).method(method).build();
			eventBus.post(loggingEntity);
		}
		return response;
	}
}

Step – 4 -Create a EventBus Subscriber

Imagine ours is a large-scale application, we want a non-invasive way of pushing the metrics, the Event Bus pattern can be a good solution for this problem, For posting an event we need to call eventBus.post(object) and all the interested subscribers will be notified. For subscribing to an event, first, annotate a given method with @Subscribe and pass it an object of the type you want to consume. In the above ShoppingMonitor, we post an object of type LoggingEntity and our subscriber in LoggerListener will log it.

@Component
public class LoggerListener {

	private static final Logger LOGGER = LogManager.getLogger(LoggerListener.class);

	@Autowired
	public LoggerListener(EventBus eventBus) {
		eventBus.register(this);
	}

	@Bean
    public EventBus getEventBus() {
        return new EventBus();
    }


	@Subscribe
	public void loggingEvent(LoggingEntity loggingEntity) {
		String message = "msg=" + loggingEntity.getMessage() + ", method=" + loggingEntity.getMethod();
		if (LoggingEntity.Level.INFO.equals(loggingEntity.getLevel())) {
			LOGGER.info(message + ", level=" + loggingEntity.getLevel());
		} else if (LoggingEntity.Level.ERROR.equals(loggingEntity.getLevel())) {
			LOGGER.error(message + ", level=" + loggingEntity.getLevel());
		} else {
			return;
		}
	}
}

Filter Based Logging + MDC(Mapped Diagnostic Context)

OncePerRequestFilter : Filter base class that aims to guarantee a single execution per request dispatch, on any servlet container

MDC: The basic idea of Mapped Diagnostic Context is to provide a way to enrich log messages with information like which are passed in Request which is otherwise not available in the scope where logging actually occurs. In the log pattern, use %X mask in the Log pattern for Logging MDC maps, and is defined in the Log4j XML shown above. We have added a TraceId to MDC, which is shown in all loggers.

@Component
public class ReqResLogger extends OncePerRequestFilter {

	@Override
	protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain)
			throws ServletException, IOException {
		String TraceId = Optional.ofNullable(request.getHeader("TraceId")).orElse(UUID.randomUUID().toString());
		MDC.put("TraceId", TraceId);
		filterChain.doFilter(request, response);
		MDC.clear();
	}
}

Monitoring using Micrometer + StatsD + Graphite + Grafana

Micrometer: Micrometer is a dimensional-first metrics collection facade whose aim is to allow you to time, count, and gauge your code with a vendor-neutral API. You may select one or several monitoring systems to export your metrics data, Think of it like SLF4J, but for metrics!

StatsD: StatsD allows you to capture different types of metrics like Gauges, Timers, Counters, etc, and aggregates the data and sends it to the Backend server of your choosing.

Graphite: Graphite is a graphing library responsible for storing and rendering visual representations of this data, and Carbon is the Storage backend for Graphite. StatsD uses a simple daemon thread to send data to Graphite, hence Graphite requires other applications to collect and transfer the data points.

Grafana: Query, visualize, alert on, and understand your data no matter where it’s stored. With Grafana you can create, explore and share all of your data through beautiful, flexible dashboards.

Step – 1 -Setup StatsD, Graphite, and Grafana using Docker

docker run -d\
 --name graphite\
 --restart=always\
 -p 80:80\
 -p 81:81\
 -p 2003-2004:2003-2004\
 -p 2023-2024:2023-2024\
 -p 8125:8125/udp\
 -p 8126:8126\
 hopsoft/graphite-statsd

This starts a Docker container with the below components, Read more

• Nginx – reverse proxies the graphite dashboard
• Graphite – front-end dashboard, port 81
• Carbon – back-end
• Statsd – UDP based back-end proxy, port 8125
• Grafana – front-end dashboard (more refined than Graphite) , port 80

Step – 2 -Add dependency in POM

		<dependency>
			<groupId>io.micrometer</groupId>
			<artifactId>micrometer-registry-statsd</artifactId>
		</dependency>

Step – 3 -Add Properties

StatsD properties helps to create StatsdMeterRegistry bean based on Spring Configuration.

management.metrics.export.statsd.host=localhost
management.metrics.export.statsd.port=8125
management.metrics.export.statsd.flavor=etsy
management.metrics.export.statsd.step=2m
management.metrics.export.statsd.enabled=true
management.endpoints.web.exposure.include=health,metrics

Step – 4 -Create MetricsListener

Micrometer helps us to invoke Counter, Timer etc in vendor independent manner, Micrometer is the metrics collection facility included in Spring Boot 2’s Actuator. In the below class we are using Counter to send info to StatsD on the times the method is called.

@Component
public class MetricsListener {

	private MeterRegistry meterRegistry;

	@Autowired
	public MetricsListener(EventBus eventBus, MeterRegistry meterRegistry) {
		this.meterRegistry = meterRegistry;
		eventBus.register(this);
	}

	@Subscribe
	public void metricsEvent(LoggingEntity loggingEntity) {
		incrementCounter(loggingEntity);
	}

	public void incrementCounter(LoggingEntity loggingEntity) {
		Counter counter = null;
		String[] method = loggingEntity.getMethod().split("\\.");
		if (LoggingEntity.Status.SUCCESS.equals(loggingEntity.getStatus())) {
			counter = Counter.builder("shoppingservice").tag(method[0], method[1]).tag("status", "success")
					.register(meterRegistry);
		} else if (LoggingEntity.Status.FAILURE.equals(loggingEntity.getStatus())) {
			counter = Counter.builder("shoppingservice").tag(method[0], method[1]).tag("status", "failure")
					.register(meterRegistry);
		} else {
			return;
		}
		counter.increment(1.0);
	}

}

Step – 5 -Configure Grafana

First open the URL HTTP://localhost:80, then login using admin, admin. Select the source as our app, and configure a Panel in the Dashboard. Choose a Graph panel, and edit configuration to display the count of API called.

GithHub

GitHub account for accessing code : https://github.com/jonesjalapatgithub/shoppingApp