JUnit тесты для логирования

Логирование относится к сквозной функциональности — разбросанной по коду и, как правило, редко покрываемой юнит-тестами. Слабое покрытие тестами, очевидно, связано с тем что вывод в лог не всегда достаточно важен и воспринимается скорее как вспомогательная функция а не цель работы метода, к тому же тестировать сквозную функциональность бывает достаточно сложно.
Но когда корректность вывода в лог становится критичной или же чувство прекрасного требует от нас полного покрытия кода тестами — без тестирования логгеров становится не обойтись.

Предположим у нас есть простой класс с log4j-логгером и методом doSomethingWithInt

import org.apache.log4j.Logger;

public class ClassWithLog4JLogger {

 private static final Logger logger =  Logger.getLogger(ClassWithLog4JLogger.class);

   public void doSomethingWithInt(int i){

       logger.info(" - метод doSomethingWithInt вызван с параметром i = " +i);
       if (i>0){
           logger.info(" - параметр i больше нуля");
       }else{
           logger.info(" - параметр i меньше или равен нулю");
       }
   }
}

Мы хотим протестировать факт того что вызов метода

new ClassWithLog4JLogger().doSomethingWithInt(1);

приведет к выводу в лог

— метод doSomethingWithInt вызван с параметром i = 1
— параметр i больше нуля

Традиционный подход к тестированию предполагает, инжектирование mock-объекта (с помощью Mockitio) в тестируемый класс и, после отработки тестируемого кода, проверку того как и какие параметры передавались в mock.

Проблема в том, что инжектировать логгер в наш класс достаточно сложно — он не передается в ClassWithLog4JLogger а возвращается из static-метода, подменять returnValue которого Mockito не умеет (и у этого есть определенные основания — Mockito предназначено для тестирования объектов, в то время как static-метод относится к классу а не объекту). Но проблема, конечно, решаема — причем несколькими способами

Способ 1. Mock для log4j-Appender-а

“За неимением горничной имеем дворника...” Пусть мы не можем подменить сам логгер — но мы можем подсунуть ему mock-аппендер и убедиться, что логгер передает в аппеддер те события которые мы ожидаем.

Добавим проект JUnit и Mockito

<dependency>
   <groupId>junit</groupId>
   <artifactId>junit</artifactId>
   <version>4.12</version>
   <scope>test</scope>
</dependency>

<dependency>
   <groupId>org.mockito</groupId>
   <artifactId>mockito-all</artifactId>
   <version>1.10.19</version>
   <scope>test</scope>
</dependency>

и напишем вот такой тест

import org.apache.log4j.Appender;
import org.apache.log4j.Logger;
import org.apache.log4j.spi.LoggingEvent;
import org.junit.Assert;
import org.junit.Test;
import org.junit.runner.RunWith;
import org.mockito.ArgumentCaptor;
import org.mockito.Mock;
import org.mockito.runners.MockitoJUnitRunner;

import static org.mockito.Mockito.times;
import static org.mockito.Mockito.verify;

@RunWith(MockitoJUnitRunner.class) // тест управляется Mockito который создаст и инициализирует мок-объекты
public class ClassWithLog4JLoggerAppenderMockTest {

   @Mock
   Appender mockAppender;

   @Test
   public void doLoggingTest() {

       // Получаем логгер для нашего класса
       Logger logger = Logger.getLogger(ClassWithLog4JLogger.class);
       // Передаем логгеру mock-аппендер
       logger.addAppender(mockAppender);

       // вызываем тестируемый метод
       ClassWithLog4JLogger classWithLog4JLogger = new ClassWithLog4JLogger();
       classWithLog4JLogger.doSomethingWithInt(1);

       // 'перехватчик' передаваемых в mock параметров
       ArgumentCaptor<LoggingEvent> eventArgumentCaptor = ArgumentCaptor.forClass(LoggingEvent.class);

       //проверяем, что аппендер вызывался два раза
       verify(mockAppender, times(2)).doAppend(eventArgumentCaptor.capture());
       //проверяем с какими параметрами вызывался аппендер
       Assert.assertEquals(" - метод doSomethingWithInt вызван с параметром i = 1", eventArgumentCaptor.getAllValues().get(0).getMessage());
       Assert.assertEquals(" - параметр i больше нуля", eventArgumentCaptor.getAllValues().get(1).getMessage());

//проверяем с какими параметрами вызывался аппендер (уровень логирования)
Assert.assertEquals(Level.INFO, eventArgumentCaptor.getAllValues().get(0).getLevel());
Assert.assertEquals(Level.INFO, eventArgumentCaptor.getAllValues().get(1).getLevel());

   }
}

Все вроде бы достаточно просто и не нуждается в пояснении.

Единственный минус такого подхода — так как мы тестируем не логгер а аппендер то мы проверяем не аргументы методов логгера а аргументы которые логгер передает аппендеру (LoggingEvent-ы), а их верификация занимает чуть больше строчек кода.

Данный подход сработает и в том случае если в качестве логгера используется slf4J Это надстройка над log4j (и еще несколькими фреймворками логирования), позволяющая, например, выводить в лог параметры без конкатинации строк (см. пример ниже). Сам slf4J-логгер не имеет методов для добавления аппендера. Но при этом он в процессе работы использует нижестоящий фреймворк (из найденных в classpath). Если этим фреймворком будет log4j то мы можем подсунуть mock-аппендер в log4j-логгер — он в свою очередь будет вызван из slf4J

Итак, добавляем зависимости на slf4j и его связку с log4j

<dependency>
   <groupId>org.slf4j</groupId>
   <artifactId>slf4j-api</artifactId>
   <version>1.7.25</version>
</dependency>

<dependency>
   <groupId>org.slf4j</groupId>
   <artifactId>slf4j-log4j12</artifactId>
   <version>1.7.25</version>
</dependency>

И протестируем класс почти такой же как в предыдущем примере — отличие только в логгере и передачи параметров в лог (теперь без конкатенации строк)

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class ClassWithSlf4JLogger {

   private static final Logger logger = LoggerFactory.getLogger(ClassWithSlf4JLogger.class);

   public void doSomethingWithInt(int i) {

       logger.info(" - метод doSomethingWithInt вызван с параметром i = {}", i);
       if (i > 0) {
           logger.info(" - параметр i больше нуля");
       } else {
           logger.info(" - параметр i больше или равен нулю");
       }
   }
}

Тест для него останется точно таким же — изменится только название класса для которого получаем логгер (при том что это по-прежнему log4j а не slf4j логгер)!

Logger logger = Logger.getLogger(ClassWithSlf4JLogger.class);

Способ 2. Подмена slf4j-имплементации.
Но что если мы все же хотим подменить не аппендер а сам логгер? Это таки-возможно. Как уже говорилось выше — slf4 использует на выбор один из нижестоящих фреймворков (log4j, logback и т.д.) Можно добавить в проект еще одну реализацию и при этом удалить из classpath остальные — тогда slf4 “подхватит” именно ее. А в тестовой реализации логгера есть методы позволяющие проверить его вызовы.

Итак — добавляем зависимость

<dependency>
   <groupId>uk.org.lidalia</groupId>
   <artifactId>slf4j-test</artifactId>
   <version>1.2.0</version>
   <scope>test</scope>
</dependency>

и — ВАЖНО(!) удаляем в процессе сборки другие slf4j-логгеры если они есть в проекте.

<build>
   <plugins>
       <plugin>
           <artifactId>maven-surefire-plugin</artifactId>
           <configuration>
               <classpathDependencyExcludes>
                   <classpathDependencyExcludes>org.slf4j:slf4j-log4j12</classpathDependencyExcludes>
               </classpathDependencyExcludes>
           </configuration>
       </plugin>
   </plugins>
</build>

Тест (для класса, используемого в прошлом примере) выглядит крайне просто

import org.junit.After;
import org.junit.Assert;
import org.junit.Test;
import uk.org.lidalia.slf4jtest.TestLogger;
import uk.org.lidalia.slf4jtest.TestLoggerFactory;

public class ClassWithSlf4JTestLoggerTest {

   //получаем тестовый логгер
   TestLogger logger = TestLoggerFactory.getTestLogger(ClassWithSlf4JLogger.class);

   @Test
   public void doLoggingTest() {

       ClassWithSlf4JLogger classWithSlf4JLogger = new ClassWithSlf4JLogger();
       classWithSlf4JLogger.doSomethingWithInt(1);

       //проверяем сообщения передаваемые в логгер
       Assert.assertEquals(" - метод doSomethingWithInt вызван с параметром i = {}", logger.getLoggingEvents().asList().get(0).getMessage());
       Assert.assertEquals(1, logger.getLoggingEvents().asList().get(0).getArguments().get(0));
       Assert.assertEquals(" - параметр i больше нуля", logger.getLoggingEvents().asList().get(1).getMessage());
       Assert.assertEquals(2,  logger.getLoggingEvents().asList().size());
   }

   @After
   public void clearLoggers() {
       TestLoggerFactory.clear();
   }
}

Проще некуда. Но есть и минус — работать тест будет только в связке с maven-ом или другой системой сборки которая удалит классы других логгеров, при этом предыдущий тест, заточенный на slf4j-log4j не отработает. На мой взгляд это не очень удобно так как сковывает нас в используемых средствах (обязательно запуск мавеном) и инструментах (не использование в тестах других логгеров).

Способ 3. Mock-логгер при помощи PowerMock

PowerMock — это как Mockito. Но круче. Чем круче? Тем, что может работать со static-методами, финальными классами, protected и даже private полями… Эдакий молоток в ювелирной лавке (кстати, именно кувалда изображена на эмблеме PowerMock) — в повседневном использовании инструмент слишком мощный, но иногда и без него — никуда. Вот и для тестирования логирования он отлично подходит — мы просто переопределялем метод LoggerFactory.getLogger и подсовываем ему наш mock-объект,

<dependency>
   <groupId>org.powermock</groupId>
   <artifactId>powermock-api-mockito</artifactId>
   <version>1.7.3</version>
   <scope>test</scope>
</dependency>

<dependency>
   <groupId>org.powermock</groupId>
   <artifactId>powermock-module-junit4</artifactId>
   <version>1.7.3</version>
   <scope>test</scope>
</dependency>

import org.junit.Test;
import org.junit.runner.RunWith;
import org.mockito.InOrder;
import org.mockito.Mockito;
import org.powermock.api.mockito.PowerMockito;
import org.powermock.core.classloader.annotations.PrepareForTest;
import org.powermock.modules.junit4.PowerMockRunner;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

import static org.mockito.Matchers.any;
import static org.mockito.Matchers.anyString;
import static org.mockito.Matchers.anyVararg;
import static org.powermock.api.mockito.PowerMockito.mock;

@RunWith(PowerMockRunner.class)
// информируем PowerMock что придется вносить изменения в класс LoggerFactory
@PrepareForTest({LoggerFactory.class})
public class PowerMockitoLoggingTest {

   // наш фейковый логгер
   private static Logger logger = mock(Logger.class);;

   // перееопределяем работу метода LoggerFactory.getLogger - теперь при вызове всегда вернет наш логгер
   static{
       PowerMockito.spy(LoggerFactory.class);
       try {
           PowerMockito.doReturn(logger).when(LoggerFactory.class, "getLogger",
                   any());
       }catch (Exception e){
           e.printStackTrace();
       }
   }

   @Test
   public void doLoggingTest() {

       ClassWithSlf4JLogger classWithSlf4JLogger = new ClassWithSlf4JLogger();
       classWithSlf4JLogger.doSomethingWithInt(1);

       //протестируем вызовы нашего логгера.
       // ради разнообразия - убедимся заодно в том, что методы логгера вызывались не просто с верными параметрами но и в нужном порядке
       InOrder inOrd = Mockito.inOrder(logger);
       inOrd.verify(logger).info(" - метод doSomethingWithInt вызван с параметром i = {}",1);
       inOrd.verify(logger).info(" - параметр i больше нуля");
       Mockito.verify(logger, Mockito.times(1)).info(anyString());
       Mockito.verify(logger, Mockito.times(1)).info(anyString(), anyVararg());
   }

Резюме

Все способы имеют право на существование. Мокирование аппендера представляется наиболее простым, не требующем использования новых (кроме JUnit и Mockito) библиотек, но не работает непосредственно с логгером.

Slf4j-test требует минимум кода — но заставляет играться с подменой классов в classpath. А PowerMock достаточно прост и позволяет инжектить в тестируемый класс mock-логгер.

Код примеров