Логирование относится к сквозной функциональности — разбросанной по коду и, как правило, редко покрываемой юнит-тестами. Слабое покрытие тестами, очевидно, связано с тем что вывод в лог не всегда достаточно важен и воспринимается скорее как вспомогательная функция а не цель работы метода, к тому же тестировать сквозную функциональность бывает достаточно сложно.
Но когда корректность вывода в лог становится критичной или же чувство прекрасного требует от нас полного покрытия кода тестами — без тестирования логгеров становится не обойтись.
Предположим у нас есть простой класс с log4j-логгером и методом doSomethingWithInt
Мы хотим протестировать факт того что вызов метода
приведет к выводу в лог
— метод doSomethingWithInt вызван с параметром i = 1
— параметр i больше нуля
Традиционный подход к тестированию предполагает, инжектирование mock-объекта (с помощью Mockitio) в тестируемый класс и, после отработки тестируемого кода, проверку того как и какие параметры передавались в mock.
Проблема в том, что инжектировать логгер в наш класс достаточно сложно — он не передается в ClassWithLog4JLogger а возвращается из static-метода, подменять returnValue которого Mockito не умеет (и у этого есть определенные основания — Mockito предназначено для тестирования объектов, в то время как static-метод относится к классу а не объекту). Но проблема, конечно, решаема — причем несколькими способами
“За неимением горничной имеем дворника...” Пусть мы не можем подменить сам логгер — но мы можем подсунуть ему mock-аппендер и убедиться, что логгер передает в аппеддер те события которые мы ожидаем.
Добавим проект JUnit и Mockito
и напишем вот такой тест
Все вроде бы достаточно просто и не нуждается в пояснении.
Единственный минус такого подхода — так как мы тестируем не логгер а аппендер то мы проверяем не аргументы методов логгера а аргументы которые логгер передает аппендеру (LoggingEvent-ы), а их верификация занимает чуть больше строчек кода.
Данный подход сработает и в том случае если в качестве логгера используется slf4J Это надстройка над log4j (и еще несколькими фреймворками логирования), позволяющая, например, выводить в лог параметры без конкатинации строк (см. пример ниже). Сам slf4J-логгер не имеет методов для добавления аппендера. Но при этом он в процессе работы использует нижестоящий фреймворк (из найденных в classpath). Если этим фреймворком будет log4j то мы можем подсунуть mock-аппендер в log4j-логгер — он в свою очередь будет вызван из slf4J
Итак, добавляем зависимости на slf4j и его связку с log4j
И протестируем класс почти такой же как в предыдущем примере — отличие только в логгере и передачи параметров в лог (теперь без конкатенации строк)
Тест для него останется точно таким же — изменится только название класса для которого получаем логгер (при том что это по-прежнему log4j а не slf4j логгер)!
Способ 2. Подмена slf4j-имплементации.
Но что если мы все же хотим подменить не аппендер а сам логгер? Это таки-возможно. Как уже говорилось выше — slf4 использует на выбор один из нижестоящих фреймворков (log4j, logback и т.д.) Можно добавить в проект еще одну реализацию и при этом удалить из classpath остальные — тогда slf4 “подхватит” именно ее. А в тестовой реализации логгера есть методы позволяющие проверить его вызовы.
Итак — добавляем зависимость
и — ВАЖНО(!) удаляем в процессе сборки другие slf4j-логгеры если они есть в проекте.
Тест (для класса, используемого в прошлом примере) выглядит крайне просто
Проще некуда. Но есть и минус — работать тест будет только в связке с maven-ом или другой системой сборки которая удалит классы других логгеров, при этом предыдущий тест, заточенный на slf4j-log4j не отработает. На мой взгляд это не очень удобно так как сковывает нас в используемых средствах (обязательно запуск мавеном) и инструментах (не использование в тестах других логгеров).
PowerMock — это как Mockito. Но круче. Чем круче? Тем, что может работать со static-методами, финальными классами, protected и даже private полями… Эдакий молоток в ювелирной лавке (кстати, именно кувалда изображена на эмблеме PowerMock) — в повседневном использовании инструмент слишком мощный, но иногда и без него — никуда. Вот и для тестирования логирования он отлично подходит — мы просто переопределялем метод LoggerFactory.getLogger и подсовываем ему наш mock-объект,
Все способы имеют право на существование. Мокирование аппендера представляется наиболее простым, не требующем использования новых (кроме JUnit и Mockito) библиотек, но не работает непосредственно с логгером.
Slf4j-test требует минимум кода — но заставляет играться с подменой классов в classpath. А PowerMock достаточно прост и позволяет инжектить в тестируемый класс mock-логгер.
Код примеров
Но когда корректность вывода в лог становится критичной или же чувство прекрасного требует от нас полного покрытия кода тестами — без тестирования логгеров становится не обойтись.
Предположим у нас есть простой класс с 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-логгер.
Код примеров
Комментарии (4)
Andrey_V_Markelov
17.12.2017 16:02Спасибо за статью. Отлично все резюмировали. Просто хочу доьавить, что jmockit также позволяет «замокировать» логгер класс.
senpay
Спасибо за статью!
Как вы думаете, есть ли смысл покрывать логику логирования юнит тестами? Врядли каждый вывод в лог стоит текста, а критичные можно попробовать протестировать Е2Е тестами.
al_stal Автор
Вам спасибо! Думаю, логику логирования стоит проверять в том случае если она имеет смысл в контексте работы программы — то есть, например, если в ТЗ програмы сказано, что выполнение программой определенных действий должно журналироваться — этот факт надо проверять тестами. А если же логирование выполняет вспомогательную функцию то тестирование уже не строго обязательно (хотя адепты 100% тестирования и утилиты, проверяющие покрытие кода тестами, со мной не согласятся...)