How to log execution time for cucumber steps

Hi folks , this post is more a continuation of Cucumber 6 Spring Integration, in case you didn’t read Cucumber integration post, please do for better understanding.

In this post we will extend the existing project by adding a useful functional of logging execution time for every cucumber step, without adding making any changes in existing steps.

In order to do this we will start with following steps:

1. Adding Spring AOP dependency

AOP is a programming paradigm that aims to increase modularity by allowing the separation of cross-cutting concerns. It does so by adding additional behavior to existing code without modification of the code itself. Instead, we can declare this new code and these new behaviors separately. Spring’s AOP framework helps us implement these cross-cutting concerns. A good introduction in AOP can be found here.

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

2. Add Spring AOP annotation on configuration

In order to enable AOP we will need to add @EnableAspectJAutoProxy annotation on our test configuration class. My configuration class will be following :

@Configuration
@ComponentScan(basePackages = {"com.exception.demo"})
@EnableAspectJAutoProxy
public class TestConfig {
}

3. Creating Step Argument Aspect

Following service is the magic of AOP , where we will add logic that will be executed before and after step execution. In our case this is a simple logic that will log execution time of every step.

import lombok.extern.log4j.Log4j2;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Pointcut;
import org.aspectj.lang.reflect.MethodSignature;
import org.springframework.stereotype.Component;
import org.springframework.util.StopWatch;

@Aspect
@Component
@Log4j2
public class StepArgumentAspect {

    @Pointcut("@annotation(io.cucumber.java.en.Given)")
    public void givenStepPointCut() {
    }

    @Pointcut("@annotation(io.cucumber.java.en.When)")
    public void whenStepPointCut() {
    }

    @Pointcut("@annotation(io.cucumber.java.en.Then)")
    public void thenStepPointCut() {
    }

    @Pointcut("@annotation(io.cucumber.java.en.And)")
    public void andStepPointCut() {
    }

    @Pointcut("@annotation(io.cucumber.java.en.But)")
    public void butStepPointCut() {
    }

    @Around("givenStepPointCut() || whenStepPointCut()||thenStepPointCut()||andStepPointCut()||butStepPointCut()")
    public Object processStepArguments(ProceedingJoinPoint joinPoint) throws Throwable {
        MethodSignature methodSignature = (MethodSignature) joinPoint.getSignature();

        String className = methodSignature.getDeclaringType().getSimpleName();
        String methodName = methodSignature.getName();

        StopWatch stopWatch = new StopWatch(className + "->" + methodName);
        stopWatch.start(methodName);
        Object result = joinPoint.proceed();
        stopWatch.stop();

        log.info(stopWatch.shortSummary());

        return result;
    }
}

How you can see we have created a point cut for every type of cucumber 6 step annotation, after that we have added all points cut in @Around annotation and added logic for logging.

We are using logback in order to log message for this we will need to add logback dependency.

4. Adding logback dependency

This step is very simple by just adding two dependency that works well with our technologies, logback and lombok.

        <dependency>
            <groupId>org.projectlombok</groupId>
            <artifactId>lombok</artifactId>
            <version>1.18.10</version>
            <scope>provided</scope>
        </dependency>
        <dependency>
            <groupId>ch.qos.logback</groupId>
            <artifactId>logback-classic</artifactId>
            <version>1.2.3</version>
        </dependency>

In case you did all right you will found following log after every step of your project:

2021-03-25 12:25:03.659  INFO 15620 --- [           main] com.exception.demo.StepArgumentAspect    : StopWatch 'BasicSteps->userPrint': running time = 28556800 ns

That’s all that are wanna to share right now, try it, experiment it and ENJOY TESTING! Link to GitHub project: https://github.com/steti93/exception-handling