Back to Spring Boot Course

Spring Boot is a very helpful framework. It allows us to forget about the majority of the configuration settings, many of which it opinionatedly auto-tunes.

When using Spring Boot Starters, Logback is used for logging by default.

Logback is one of the most widely used logging frameworks in the Java Community. It's a replacement for its predecessor, Log4j. Logback offers a faster implementation, provides more options for configuration, and more flexibility in archiving old log files.

The Logback architecture is comprised of three classes: Logger, Appender, and Layout.

A Logger is a context for log messages. This is the class that applications interact with to create log messages.

Appenders place log messages in their final destinations. A Logger can have more than one Appender. We generally think of Appenders as being attached to text files, but Logback is much more potent than that.

Layout prepares messages for outputting. Logback supports the creation of custom classes for formatting messages, as well as robust configuration options for the existing ones.

Let's add the logback dependency in pom.xml

<dependency>
    <groupId>net.logstash.logback</groupId>
    <artifactId>logstash-logback-encoder</artifactId>
    <version>8.0</version>
</dependency>
<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>slf4j-api</artifactId>
</dependency>

When a file in the classpath has one of the following names, Spring Boot will automatically load it over the default configuration:

• logback-spring.xml
• logback.xml
• logback-spring.groovy
• logback.groovy

Let's create logback.xml with custom log configuration and place it in resources folder.

Let's start our application now.

{"@timestamp":"2024-12-07T22:57:42.0312104+05:30","severity":"INFO","service":"emp-mgmt-service","thread":"main","class":"o.s.b.w.embedded.tomcat.TomcatWebServer","methodName":"start","lineNo":"243","message":"Tomcat started on port 8080 (http) with context path '/'","stacktrace":""}
{"@timestamp":"2024-12-07T22:57:42.0432566+05:30","severity":"INFO","service":"emp-mgmt-service","thread":"main","class":"c.p.e.EmployeeManagementServiceApplication","methodName":"logStarted","lineNo":"59","message":"Started EmployeeManagementServiceApplication in 5.087 seconds (process running for 6.024)","stacktrace":""}

Structured Logging

Spring Boot 3.4 introduced a feature called structure logging which enables us to produce log outputs in a clear and machine-readable style.

By utilizing structured logging, we can effectively capture and organize log information, making it easier to parse and analyze with other tools. This approach not only enhances the readability of logs for humans but also streamlines the process of aggregating and searching through log data, ultimately leading to more efficient debugging and monitoring of applications.

Out-of-the-box supports the following JSON formats:

• Elastic Common Schema (ecs)
• Graylog Extended Log Format (gelf)
• Logstash (logstash)

The preferred one is ECS so that tools like Elasticsearch, Kibana, and other Elastic Stack products can seamlessly integrate, ensuring better consistency, searchability, and scalability of logs.

There is no need to add any dependencies like above instead we need to just configure the below property in application.yml.

logging:
  structured:
    format:
      console: ecs

Application startup logs will look like this.

{"@timestamp":"2024-12-18T13:37:19.892331800Z","log.level":"INFO","process.pid":13788,"process.thread.name":"main","service.name":"emp-mgmt-service","log.logger":"org.springframework.boot.web.embedded.tomcat.TomcatWebServer","message":"Tomcat started on port 8080 (http) with context path '\/'","ecs.version":"8.11"}
{"@timestamp":"2024-12-18T13:37:19.904333Z","log.level":"INFO","process.pid":13788,"process.thread.name":"main","service.name":"emp-mgmt-service","log.logger":"com.praveen.employee.EmployeeManagementServiceApplication","message":"Started EmployeeManagementServiceApplication in 10.094 seconds (process running for 11.872)","ecs.version":"8.11"}

It's always best to create an AOP Advice class for logging the statements in controller and service classes, Also we can create an AOP Advice class for logging the execution time.

Before proceeding, Lets learn about AOP.

What is AOP(Aspect Oriented Programming)?

AOP is a programming methodology which helps to manage cross cutting concern like transaction management, logging,security etc.

Why AOP?

It provides the pluggable way to dynamically add the additional concern before,after or around the actual business logic.

Aspects enable modularization of concerns.

Uses of Spring AOP

• Remove tight coupling between cross cutting concerns and business logic
• Easy to maintain code in present and future.

AOP Core Concepts

Aspect

An Aspect is a class that implements the Java Enterprise application concerns which cuts through multiple classes like transaction management,logging,security etc.An aspect will be configured using annotation @Aspect.

To enable AspectJ annotations in Spring projects, we need to configure @EnableAspectJAutoProxy in the aspect class and incase of spring boot project we need to configure @EnableAspectJAutoProxy in main class.

Advice

Advice represents an action taken by an aspect at a particular join point.

• @Before – Adviced to execute before the joint point.
• @AfterReturning – Adviced to execute after the joint point complete.
• @After – Adviced to execute after the joint point.
• @AfterThrowing- Adviced to execute after the joint point exists by throwing an exception
• @Around – Advice that surrounds a joint point like method invocation

Joinpoint

A point in a program such as method execution,exception handling etc.

Pointcut

A pointcut is an expression language of AOP that matches joint points which determines whether Advice needs to be executed or not.

• Execution
• This
• Target
• Args
• @target
• @args
• @within
• @annotation

Advisor

An advisor is a combination of a pointcut and an advice.

An advisor knows about what advices are needed for what joinpoints identified by a pointcut.

Target & Proxy

Target is a business class object, before AOP feature is applied for it.

Proxy is also a business class object, after AOP feature is applied to it.

Weaving

Linking aspects with other application types or objects to create an advised object. This can be done at compile time (using the AspectJ compiler, for example), load time, or at runtime. Spring AOP, like other pure Java AOP frameworks, performs weaving at runtime.

Weaving is a process of converting a target object into a proxy object by adding advices to it. For example, a web-container converts a jsp into equivalent servlet. Here jsp is a target and servlet is a proxy. This process is called weaving.

Annotations Allowed Attributes

• @Pointcut value
• @Before value
• @AfterReturning pointcut, value, returning
• @After value
• @AfterThrowing pointcut, value, throwing
• @Around value

Now Let's create an AOP Advice class for logging the execution time.

Lets include AOP dependency in pom.xml

<dependency>
  <groupId>org.springframework.boot</groupId>
  <artifactId>spring-boot-starter-aop</artifactId>
</dependency>

AOP Advice class for Logging

package com.praveen.employee.aop;

import java.util.Arrays;
import java.util.stream.Collectors;

import org.aspectj.lang.JoinPoint;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.AfterThrowing;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.reflect.MethodSignature;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.stereotype.Component;

import com.praveen.employee.common.Constants;

/**
 * Aspect that handles logging for method executions and exceptions. It
 * intercepts methods annotated with @LoggingAspect to log request and response
 * data, and logs exceptions thrown in the GlobalExceptionHandler.
 */
@Aspect
@Component
public class LoggingAdvice {

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

	/**
	 * Advice that wraps around method execution to log request and response data.
	 *
	 * @param pjp the join point representing the method execution
	 * @return the result of the method execution
	 * @throws Throwable if the method execution throws an exception
	 */
	@Around("@annotation(com.praveen.employee.aop.LoggingAspect)")
	public Object logging(ProceedingJoinPoint pjp) throws Throwable {
		var methodSignature = (MethodSignature) pjp.getSignature();
		var className = methodSignature.getDeclaringType().getSimpleName();
		var methodName = methodSignature.getName();
		var requestData = constructData(pjp);
		log.info("{} for {}.{}: Request Data={}", Constants.INITIAL_REQUEST, className, methodName, requestData);
		var proceed = pjp.proceed();
		log.info("{} for {}.{}: Response Data={}", Constants.FINAL_RESPONSE, className, methodName, proceed);
		return proceed;
	}

	/**
	 * Advice that logs exceptions thrown by methods in the GlobalExceptionHandler.
	 *
	 * @param joinPoint the join point representing the method execution
	 * @param ex        the exception thrown
	 */
	@AfterThrowing(pointcut = "execution(* com.praveen.employee.controller.advice.GlobalExceptionHandler.*(..))", throwing = "ex")
	public void logException(JoinPoint joinPoint, Exception ex) {
		var className = joinPoint.getSignature().getDeclaringTypeName();
		var methodName = joinPoint.getSignature().getName();
		var exceptionMessage = ex.getMessage();
		var exceptionDetails = Arrays.stream(joinPoint.getArgs()).map(String::valueOf)
				.collect(Collectors.joining(",", "[", "]"));
		log.error("Exception in {}.{}: Exception Message={}, Details={}", className, methodName, exceptionMessage,
				exceptionDetails);
	}

	/**
	 * Constructs a string representation of the method arguments.
	 *
	 * @param jp the join point representing the method execution
	 * @return a string representation of the arguments
	 */
	private String constructData(JoinPoint jp) {
		return Arrays.stream(jp.getArgs()).map(String::valueOf).collect(Collectors.joining(",", "[", "]"));
	}
}

Let's include @LoggingAspect annotation on top of any method where you want to log the incoming request and outgoing response for a method.

@RestController
@Validated
@RequestMapping("/api/v1")
public class EmployeeManagementController {

	private final EmployeeManagementService employeeManagementService;

	public EmployeeManagementController(EmployeeManagementService employeeManagementService) {
		this.employeeManagementService = employeeManagementService;
	}

	@GetMapping(value = "/employees/search", produces = MediaType.APPLICATION_JSON_VALUE)
	@LoggingAspect
	public List<Employee> getEmployeeByName(@RequestParam @NotBlank @Size(min = 5) String name) {
		return employeeManagementService.getEmployeeByName(name);
	}
}

Let's go to http://localhost:8080/api/v1/employees/search?name=Praveen and check the logs.

{"@timestamp":"2024-12-18T13:45:37.053542600Z","log.level":"INFO","process.pid":13788,"process.thread.name":"http-nio-8080-exec-3","service.name":"emp-mgmt-service","log.logger":"com.praveen.employee.aop.LoggingAdvice","message":"Initial Request for EmployeeManagementController.getEmployeeByName: Request Data=[Praveen]","ecs.version":"8.11"}
{"@timestamp":"2024-12-18T13:45:37.456122300Z","log.level":"INFO","process.pid":13788,"process.thread.name":"http-nio-8080-exec-3","service.name":"emp-mgmt-service","log.logger":"com.praveen.employee.aop.LoggingAdvice","message":"Final Response for EmployeeManagementController.getEmployeeByName: Response Data=[Employee [id=1, name=Praveen, designation=Technical Architect, salary=5000000, location=Hyderabad]]","ecs.version":"8.11"}

AOP Advice class for Execution Time

package com.praveen.employee.aop;

import java.lang.annotation.ElementType;
import java.lang.annotation.Retention;
import java.lang.annotation.RetentionPolicy;
import java.lang.annotation.Target;

/**
 * Annotation to indicate that the execution time of a method should be tracked.
 * Methods annotated with @TrackExecutionTime will have their execution duration
 * measured and logged by the ExecutionTimeTrackerAdvice aspect.
 */
@Target(ElementType.METHOD)
@Retention(RetentionPolicy.RUNTIME)
public @interface TrackExecutionTime {
}

package com.praveen.employee.aop;

import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.reflect.MethodSignature;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.stereotype.Component;
import org.springframework.util.StopWatch;

/**
 * Aspect that tracks the execution time of methods annotated
 * with @TrackExecutionTime. It uses Spring AOP to intercept method calls and
 * measure their execution duration.
 */
@Aspect
@Component
public class ExecutionTimeTrackerAdvice {

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

	/**
	 * Advice that wraps around method execution to measure and log execution time.
	 *
	 * @param pjp the join point representing the method execution
	 * @return the result of the method execution
	 * @throws Throwable if the method execution throws an exception
	 */
	@Around("@annotation(com.praveen.employee.aop.TrackExecutionTime)")
	public Object trackTime(ProceedingJoinPoint pjp) throws Throwable {
		var methodSignature = (MethodSignature) pjp.getSignature();

		var className = methodSignature.getDeclaringType().getSimpleName();
		var methodName = methodSignature.getName();
		final var stopWatch = new StopWatch();

		stopWatch.start();
		Object result = pjp.proceed();
		stopWatch.stop();

		log.info("Execution time of {}.{} :: {} ms", className, methodName, stopWatch.getTotalTimeMillis());

		return result;
	}

}

Let's include @TrackExecutionTime annotation on top of any method where you want to find the execution time for a particular method.

@RestController
@Validated
@RequestMapping("/api/v1")
public class EmployeeManagementController {

	private final EmployeeManagementService employeeManagementService;

	public EmployeeManagementController(EmployeeManagementService employeeManagementService) {
		this.employeeManagementService = employeeManagementService;
	}

	@GetMapping(value = "/employees/search", produces = MediaType.APPLICATION_JSON_VALUE)
	@LoggingAspect
    @TrackExecutionTime
	public List<Employee> getEmployeeByName(@RequestParam @NotBlank @Size(min = 5) String name) {
		return employeeManagementService.getEmployeeByName(name);
	}
}

Let's go to http://localhost:8080/api/v1/employees/search?name=Praveen and check the logs.

{"@timestamp":"2024-12-18T13:45:37.053542600Z","log.level":"INFO","process.pid":13788,"process.thread.name":"http-nio-8080-exec-3","service.name":"emp-mgmt-service","log.logger":"com.praveen.employee.aop.LoggingAdvice","message":"Initial Request for EmployeeManagementController.getEmployeeByName: Request Data=[Praveen]","ecs.version":"8.11"}
{"@timestamp":"2024-12-18T13:45:37.456122300Z","log.level":"INFO","process.pid":13788,"process.thread.name":"http-nio-8080-exec-3","service.name":"emp-mgmt-service","log.logger":"com.praveen.employee.aop.LoggingAdvice","message":"Final Response for EmployeeManagementController.getEmployeeByName: Response Data=[Employee [id=1, name=Praveen, designation=Technical Architect, salary=5000000, location=Hyderabad]]","ecs.version":"8.11"}
{"@timestamp":"2024-12-18T13:45:37.457331400Z","log.level":"INFO","process.pid":13788,"process.thread.name":"http-nio-8080-exec-3","service.name":"emp-mgmt-service","log.logger":"com.praveen.employee.aop.ExecutionTimeTrackerAdvice","message":"Execution time of EmployeeManagementController.getEmployeeByName :: 404 ms","ecs.version":"8.11"}