Enforcing Logging best practices by writing ArchUnit tests


We have following three logging best practices:

  1. All loggers should be final variables. So, we prefer
   private final Logger logger = LoggerFactory
.getLogger(MyService.class); // good

Instead of

   private static final Logger LOGGER = LoggerFactory
.getLogger(MyService.class); // bad

Using constant based syntax makes code look ugly and require developers to use shift key for typing upper case variable name. This breaks the flow so we prefer to use field variable naming.

  1. All logs should have description and context So, we prefer
   logger.info("Event is alreay processed so not 
processing it again [eventId={}, eventDbId={}, 
eventType={}]", 
eventId, event.getId(), eventType); // good

instead of

   logger.info("Event is already processed 
so not processing"); // bad

We want logger statement to have enough context so that we can debug problems. The bad logging statement does not help you understand for which event this log statement was logged. All of these statements look similar.

  1. All error logs should have the exception in the context So, we prefer
   logger.error("Exception while processing event 
[eventId={}]", eventId, exception); // good

instead of

   logger.error("Exception while processing event 
[eventId={}]", eventId); // bad

To help developers discover these before raising their pull requests we have written ArchUnit tests for enforcing these practices. So, local build fails in case they violate these best practices. You can read my earlier post on ArchUnit[1] in case you are new to it.

You write ArchUnit tests by defining ArchUnit rules. The rule for our first best practice logger should be final is below.

public static ArchRule loggerShouldBeFinal() {
    return fields()
            .that().haveRawType(Logger.class)
            .should().bePrivate().andShould().beFinal()
            .andShould().notBeStatic()
            .allowEmptyShould(true);
}

The next two rules are bit more involved.

public static ArchRule noInfoLoggingWithoutContext() {
    ArchCondition<JavaClass> loggerWithOutContext =
            callMethodWhere(
                    target(name("info"))
                            .and(target(owner(assignableTo(Logger.class))))
                            .and(target(rawParameterTypes(new DescribedPredicate<>("logger.info without context") {
                                @Override
                                public boolean test(List<JavaClass> methodParameters) {
                                    return methodParameters.size() <= 1;
                                }
                            })))).as("use logger.info without context");
    return noClasses()
            .should(loggerWithOutContext);
}

public static ArchRule noErrorLoggingWithoutContextAndException() {
    ArchCondition<JavaClass> loggerWithOutContext =
            callMethodWhere(
                    target(name("error"))
                            .and(target(owner(assignableTo(Logger.class))))
                            .and(target(rawParameterTypes(new DescribedPredicate<>("logger.error without exception context") {
                                @Override
                                public boolean test(List<JavaClass> methodParameters) {
                                    boolean hasNoContext = methodParameters.size() <= 1;
                                    boolean hasNoExceptionInContext =
                                            methodParameters.stream()
                                                    .noneMatch(j -> j.isAssignableTo(Throwable.class));
                                    return hasNoContext || hasNoExceptionInContext;
                                }
                            })))).as("use logger.error without context");
    return noClasses()
            .should(loggerWithOutContext);
}

References

  1. https://shekhargulati.com/2020/05/04/using-archunit-to-enforce-architecture-best-practices/

One thought on “Enforcing Logging best practices by writing ArchUnit tests”

  1. Thanks for the examples. It was really helpful.
    I am trying to create ArcRule to check log parameters, that should not to be of specific custom class type.

    So I created a ArcCondition like this

    ArchCondition loggerWithOutContext =
    callMethodWhere(
    target(name(“info”))
    .and(target(owner(assignableTo(Logger.class))))
    .and(target(rawParameterTypes(new DescribedPredicate<List>(“logger.info without entity class context”) {
    @Override public boolean test(List methodParameters) {
    boolean hasNoEntityClassInContext =
    methodParameters.stream().anyMatch(j -> j.isAssignableTo(ExampleEntity.class));
    }

    j.isAssignableTo(ExampleEntity.class) condition is always false , though the ExampleEntity object is passed isn passed as parameter like this

    ExampleEntity example = new ExampleEntity();
    logger.info(“some log statement {}”, example);

    Do you know how to achieve this?

    Reply

Leave a comment