Take a look at the client and the test scenario that we developed in REST API client for TestNG and Spring Boot using Apache Http Components. Part 2.

The goal is to log service calls with all parameters and responses.

I’m not going to explain why logging is very important. I assume we are on the same page.

Let’s implement the logging feature for the service client using the approach that we considered in AspectJ. How to log method with parameters in Java.

Create @LogBookService annotation

  @Retention(RetentionPolicy.RUNTIME)
  @Target(ElementType.METHOD)
  public @interface LogBookService {
  }

Logger aspect

@Aspect
@Component
public class ServiceLogger {

    private Gson gson = new GsonBuilder().setPrettyPrinting().create();

    @Around("execution(* *(..)) && @annotation(io.lenar.examples.spring.clients.log.LogBookService)")
    public Object logBookServiceMethods(ProceedingJoinPoint jp) throws Throwable {
        String methodName = jp.getSignature().getName();
        logRequest(jp, "BOOK SERVICE");

        long startTime = new Date().getTime();
        Object result = jp.proceed(jp.getArgs());
        long endTime = new Date().getTime();

        Reporter.log("\nResponse time: " + (endTime - startTime) + "ms", true);
        Reporter.log("<- " + methodName + " Response: \n" + gson.toJson(result) + "\n", true);

        return result;
    }

    private void logRequest(ProceedingJoinPoint jp, String serviceName) {
        Reporter.log(serviceName + " CALL:", true);
        String[] argNames = ((MethodSignature) jp.getSignature()).getParameterNames();
        Object[] values = jp.getArgs();
        Map<String, Object> params = new HashMap<>();
        if (argNames.length != 0) {
            for (int i = 0; i < argNames.length; i++) {
                params.put(argNames[i], values[i]);
            }
        }

        Reporter.log("-> " + jp.getSignature().getName() + " Request", true);
        if (!params.isEmpty()) Reporter.log(gson.toJson(params), true);
    }
}

One reminder - we use here Reporter.log(..) from TestNG. You can use any other logger (Log4j, Logback, SLF4J…).

Aspect weaving

The last thing we need to setup is pom.xml to properly weave our aspects.

There are some differences between Spring and non-Spring projects so carefully read this - Aspect weaving in Spring and non-Spring projects

Client with logging

And finally our client with logging looks like this

@Component
public class BookServiceClient {

    @Value("${bookService.url}")
    private String serviceUrl;

    @Autowired
    HttpClient http;

    @LogBookService
    public BooksResponse findBooks(String author) throws IOException {
        String url = author == null ? serviceUrl  : serviceUrl + "?author=" + author;
        return new BooksResponse(http.get(url));
    }

    @LogBookService
    public BooksResponse findBooks() throws IOException {
        return new BooksResponse(http.get(serviceUrl));
    }

    @LogBookService
    public BookResponse findBook(String id) throws IOException {
        return new BookResponse(http.get(serviceUrl + "/" + id));
    }

    @LogBookService
    public BookResponse createBook(Book book) throws IOException {
        return new BookResponse(http.post(serviceUrl, book));
    }

    @LogBookService
    public BookResponse updateBook(String id, Book book) throws IOException {
        return new BookResponse(http.put(serviceUrl + "/" + id, book));
    }

    @LogBookService
    public Response deleteBook(String id) throws IOException {
        return new Response(http.delete(serviceUrl + "/" + id));
    }
}

We annotated all calls that we wanted to log with @LogBookService

This is our scenario:

    @Autowired
    BookServiceClient client;

    @Test
    public void createUpdateDeleteScenarioTest() throws IOException {
        Book createdBook = client.createBook(new Book("The Book. Part 1", "John Doe")).dto();
        String id = createdBook.getId();

        List<Book> getBooks = client.findBooks().dto();
        Book getCreatedBook = getBooks.stream()
            .filter(book -> id.equals(book.getId())).findAny().orElse(null);

        Book forUpdateBook = new Book("The Book. Part 2", "Jane Doe");
        Book updatedBook = client.updateBook(id, forUpdateBook).dto();

        Book getUpdatedBook = client.findBook(id).dto();

        client.deleteBook(id);
    }

This is how our logs for the scenario look like

BOOK SERVICE CALL:
-> createBook Request
{
  "book": {
    "title": "The Book. Part 1",
    "author": "John Doe"
  }
}

Response time: 587ms
<- createBook Response: 
{
  "dto": {
    "id": "5a9f0e21efc21b00044c2644",
    "title": "The Book. Part 1",
    "author": "John Doe"
  },
  "status": {
    "code": 200
  }
}

BOOK SERVICE CALL:
-> findBooks Request

Response time: 156ms
<- findBooks Response: 
{
  "dto": [
    {
      "id": "5a9f0e21efc21b00044c2644",
      "title": "The Book. Part 1",
      "author": "John Doe"
    }
  ],
  "status": {
    "code": 200
  }
}

BOOK SERVICE CALL:
-> updateBook Request
{
  "book": {
    "title": "The Book. Part 2",
    "author": "Jane Doe"
  },
  "id": "5a9f0e21efc21b00044c2644"
}

Response time: 187ms
<- updateBook Response: 
{
  "dto": {
    "id": "5a9f0e21efc21b00044c2644",
    "title": "The Book. Part 2",
    "author": "Jane Doe"
  },
  "status": {
    "code": 200
  }
}

BOOK SERVICE CALL:
-> findBook Request
{
  "id": "5a9f0e21efc21b00044c2644"
}

Response time: 94ms
<- findBook Response: 
{
  "dto": {
    "id": "5a9f0e21efc21b00044c2644",
    "title": "The Book. Part 2",
    "author": "Jane Doe"
  },
  "status": {
    "code": 200
  }
}

BOOK SERVICE CALL:
-> deleteBook Request
{
  "id": "5a9f0e21efc21b00044c2644"
}

Response time: 125ms
<- deleteBook Response: 
{
  "status": {
    "code": 200
  }
}

Easy to read and debug.

EasyLog (Site, Source code) is an open source library that allows you to log any method or all methods of a class with one annotations. Also it supports a lot of other useful features like masking fields to pevent sensitive data from logging and many others.

EasyLog uses a similar approach to the described in the post

You may also find these posts interesting: