Metro и log4j2 в веб-приложении: боремся с утечками памяти

Добавить комментарий

В прошлой статье мы рассмотрели утечки памяти, которые возникают при остановках и переустановках веб-приложений, написанных на Java. Речь шла о выводе логов Spring через log4j2. Я показывал, каким образом нужно настроить веб-приложение так, чтобы контекст логгера уничтожался в последнюю очередь, после контекста Spring.

К сожалению «весенний» фреймворк не единственная технология, с которой могут возникнуть подобные проблемы. Сейчас я покажу, как можно легко и просто получить утечки памяти, используя log4j2 в веб-службах и на этот раз конец истории будет не таким радужным.

Если ты в курсе о чём речь и тебе знакома эта тема, то устраивайся поудобнее и читай дальше. Если же нет, то советую сначала прочитать первую статью: она введёт тебя в курс дела. Далее я буду исходить из того, что ты так и поступил.

Подготавливаем окружение

Если ты когда-нибудь разрабатывал веб-службы на Java, то с очень большой вероятностью использовал для этого библиотеки Metro. Обычно их даже не нужно явно подключать в проект: они могут быть установлены в контейнере сервлетов. На странице https://javaee.github.io/metro/download есть руководство по установке Metro в Apache Tomcat и GlassFish.

Процесс установки для томката довольно прост: необходимо выполнить ant-сценарий metro-on-tomcat.xml, после чего в его корневой директории в папке shared\lib появятся четыре новых файла: webservices-extra.jar, webservices-extra-api.jar, webservices- rt.jar, webservices-tools.jar, а в папке endorsed – файл webservices-api.jar. В случае с GlassFish и вовсе ничего делать не нужно: для него metro поставляется «из коробки».

Если ты всё сделал по инструкции, то мы можем приступить к разработке простой веб-службы и на её примере изучать поведение обоих сервлет-контейнеров. Также не лишним будет заранее предупредить тебя, дорогой читатель, что в этой статье будет на порядок более глубокое погружение в дебри «кошачьего» и «рыбьего» программного кода. Если тебя это не пугает, и ты готов к сложностям, то предлагаю сварить кофе покрепче, открыть любимую IDE и погрузиться в мир Java.

Разрабатываем SOAP-службу

Чтобы создать простейшую веб-службу, требуется написать всего несколько строк кода:

@WebService(serviceName = "MyWebService")
public class MyWebService {

    @WebMethod
    public void myWebMethod() {
        // no operation
    } 
}

Здесь мы объявили службу MyWebService с единственным методом myWebMethod.Создадим для неё также дескриптор развёртывания sun-jaxws.xml:

<?xml version="1.0" encoding="UTF-8"?>
<endpoints version="2.0" xmlns="http://java.sun.com/xml/ns/jax-ws/ri/runtime">
    <endpoint name="MyWebService"
               implementation="net.syberia.memoryleaks.metrolog4j2.MyWebService"
               url-pattern="/MyWebService" />
</endpoints>

С его помощью мы говорим библиотеке Metro о том, что у нас есть веб-служба под названием MyWebService, которая реализована в классе net.syberia.memoryleaks.metrolog4j2.MyWebService и её следует развернуть по адресу /MyWebService. Таким образом, если наше веб-приложение будет называться, к-примеру, metro-log4j2-memory-leaks, то после публикации служба будет доступна по адресу http://localhost:8080/metro-log4j2-memory-leaks/MyWebService (разумеется, если сервлет-контейнер поднят на твоей локальной машине).

В Tomcat и GlassFish веб-приложения публикуются достаточно просто через административные панели в браузере. Инструкции можно найти здесь и здесь.

Работу нашей службы можно проверить, например, с помощью программы SoapUI. Если скормить ей адрес WSDL http://localhost:8080/metro-log4j2-memory-leaks- 1.0/MyWebService?wsdl и отправить такой запрос:

<soapenv:Envelope xmlns:soapenv="http://schemas.xmlsoap.org/soap/envelope/"
xmlns:met="http://metrolog4j2.memoryleaks.syberia.net/">
   <soapenv:Header/>
   <soapenv:Body>
      <met:myWebMethod/>
   </soapenv:Body>
</soapenv:Envelope>

то получим ответ:

<S:Envelope xmlns:S="http://schemas.xmlsoap.org/soap/envelope/">
   <S:Body>
      <myWebMethodResponse xmlns="http://metrolog4j2.memoryleaks.syberia.net/"/>
   </S:Body>
</S:Envelope>

Таким образом мы можем убедиться, что программа работает.

Если бы это было краткое руководство о том, как делать свои собственные службы, то на этом мы могли бы и закончить… однако мы не ищем лёгких путей: нашему детищу нужно логирование! Иначе как ты будешь разбираться, почему упал продакшн в два часа ночи?

Создаём утечки памяти

Добавить логгер log4j2 в класс MyWebService очень легко:

@WebService(serviceName = "MyWebService")
public class MyWebService {

    private static final Logger LOGGER = LogManager.getLogger(MyWebService.class);
    
    @WebMethod
    public void myWebMethod() {
        // no operation
    } 
}

Код выглядит просто и стандартно. Однако теперь если собрать и опубликовать эту службу, то получим утечки памяти, хотя мы просто создали объект LOGGER и даже нигде его не использовали! Ещё более странно то, что если в случае с Tomcat утечки появляются при каждой остановке\переустановке службы, то в GlassFish они появляются случайным образом.

Это означает, что если сегодня ты накатил новую версию своего приложения на сервер без появления утечек памяти, то это не значит, что тебе повезёт завтра. Похоже на некую чертовщину, но это не совсем так. Давай постараемся разобраться, почему это происходит.

Утечка в Apache Tomcat

Очевидно, что утечку каким-то образом вызвал статический метод LogManager.getLogger, так как при объявлении логгера вызывается только он. В свою очередь создание объекта LOGGER могло спровоцировать обращение к классу MyWebService. Мы можем проверить это, если, например, поставим точку останова (breakpoint) внутри конструктора нашего класса:

@WebService(serviceName = "MyWebService")
public class MyWebService {

    private static final Logger LOGGER = LogManager.getLogger(MyWebService.class);

    public MyWebService() { 
        System.out.println("My breakpoint here");
    }

    @WebMethod
    public void myWebMethod() {
        // no operation
    } 
}

После этого запустим приложение в режиме отладки и, когда наш breakpoint сработает, откроем стек вызовов. В NetBeans IDE он выглядит как на рисунке ниже:

Здесь мы видим, что класс StandardContext томката вызывает WSServletContainerInitializer из библиотеки metro, который в свою очередь создаёт экземпляр нашего MyWebService. Можно предположить, что это происходит раньше, чем инициализация логгера в Log4jServletContainerInitializer.

Чтобы проверить это, можно подключить к проекту исходные коды томката. Для тестов будем использовать версию 8.5.23:

<dependency>
    <groupId>org.apache.tomcat</groupId>
    <artifactId>tomcat-catalina</artifactId>
    <version>8.5.23</version>
    <scope>provided</scope>
</dependency>

Теперь если в режиме отладки перейти на строку под номером 5196 в StandardContext, то увидим такое:

...

for (Map.Entry<ServletContainerInitializer, Set<Class<?>>> entry : initializers.entrySet()) {
    try {
        entry.getKey().onStartup(entry.getValue(),
              getServletContext());
    }

...

Здесь происходит последовательный вызов в цикле всех элементов ассоциативного массива initializers, который имеет реализацию LinkedHashMap. Это означает, что порядок элементов в массиве будет неизменным: в какой последовательности их в него поместили, в той же они будут извлекаться.

Если посмотрим на содержимое initializers, то увидим, что наше предположение было верно: логгер инициализируется последним, а значит, мы нашли причину утечек памяти. Проблема вроде бы похожа на ту, что мы разбирали в первой статье, но есть серьёзные отличия:

  1. Log4jServletContainerInitializer вызывался раньше, чем SpringServletContainerInitializer и это было правильно;
  2. В web.xml был зарегистрирован ContextLoaderListener, что и вызывало утечку памяти.

Здесь мы не создавали web.xml, да и вообще ничего особо криминального не делали. В чём же причина неверного порядка вызова инициализаторов? Ответ можно найти, если проследить по коду алгоритм заполнения initializers. Это довольно сложное и долгое упражнение по чтению чужого исходного кода, которое я здесь описывать не буду, а лишь сообщу конечный результат своих изысканий: порядок задаётся в методе load класса WebappServiceLoader.

Суть алгоритма сводится к тому, что сначала загружаются все ServletContainerInitializer томката, а потом самого приложения. При этом инициализаторы приложения сортируются только друг относительно друга, а в общий LinkedHashMap помещаются всё равно после инициализаторов томката.

Поскольку в нашем примере WSServletContainerInitializer располагается внутри томката, а Log4jServletContainerInitializer – внутри нашей службы, то web-fragment.xml с сортировкой для логгера нам здесь не помогает.

Однако в этом же методе можно обнаружить, что у томката есть возможность отключить инициализаторы по выбору с помощью настройки containerSciFilter в файле META-INF/context.xml. Отключим WSServletContainerInitializer:

<Context path="/metro-log4j2-memory-leaks"         
          containerSciFilter="com.sun.xml.ws.transport.http.servlet.WSServletContainerInitializer">
</Context>

Теперь если попробовать запустить нашу службу, то обнаружим, что она перестала работать, и этого стоило ожидать. Мы можем её снова оживить, если подключим в web.xml класс WSServletContextListener:

<?xml version="1.0" encoding="UTF-8"?>
<web-app xmlns="http://xmlns.jcp.org/xml/ns/javaee"
          xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
          xsi:schemaLocation="http://xmlns.jcp.org/xml/ns/javaee http://xmlns.jcp.org/xml/ns/javaee/web-app_3_1.xsd"
          version="3.1">
    <listener>
        <listener-class>com.sun.xml.ws.transport.http.servlet.WSServletContextListener</listener-class> 
    </listener>
</web-app>

В итоге служба заработает, а утечка памяти пропадёт. Однако сейчас мы пришли к такой же ситуации, с которой начиналась первая статья: только вместо ContextLoaderListener в web.xml зарегистрирован WSServletContextListener, а значит, мы должны были получить утечку, но её нет.

Это объясняется тем, что WSServletContextListener при уничтожении контекста пишет в лог через JUL, и log4j2 при этом не вызывается повторно. Но ситуация, когда логгер уничтожается не в последнюю очередь всё же является потенциальной проблемой, и на всякий случай следует явно указать Log4jServletContextListener до WSServletContextListener:

<?xml version="1.0" encoding="UTF-8"?>
<web-app xmlns="http://xmlns.jcp.org/xml/ns/javaee"
          xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
          xsi:schemaLocation="http://xmlns.jcp.org/xml/ns/javaee http://xmlns.jcp.org/xml/ns/javaee/web-app_3_1.xsd"
          version="3.1">
    <listener>
        <listener-class>org.apache.logging.log4j.web.Log4jServletContextListener</listener-class> 
    </listener>
    <listener>
        <listener-class>com.sun.xml.ws.transport.http.servlet.WSServletContextListener</listener-class> 
    </listener>
    <context-param>
        <param-name>isLog4jAutoInitializationDisabled</param-name>
        <param-value>true</param-value>
    </context-param>
</web-app>

Если проверить приложение на утечки памяти, то их по-прежнему нет: для пользователей томката нашлось простое и элегантное решение проблемы.

Утечка в GlassFish

С GlassFish дела обстоят хуже. Если мы попробуем воспроизвести утечку, которая была описана выше, то она может проявляться, а может и не проявляться – самая настоящая утечка Шрёдингера. При этом решение проблемы, которое было верным для Tomcat совсем не подходит для GlassFish: в нём нет ничего похожего на настройку containerSciFilter. Но ведь должен быть какой-то выход?

Если порыться в исходном коде этого сервера приложений, то вместо такой настройки найдём самый настоящий костыль:

...

for (Map.Entry<Class<? extends ServletContainerInitializer>, Set<Class<?>>> e : initializerList.entrySet()) {
    Class<? extends ServletContainerInitializer> initializer = e.getKey();     
    if (isUseMyFaces() &amp;&amp;
            Globals.FACES_INITIALIZER.equals(initializer.getName())) { 
        continue;
    }

...

То есть при последовательном запуске инициализаторов из ассоциативного массива initializerList в коде жёстко прописано, что фильтруется только FacesInitializer в случае использования библиотеки MyFaces. Других способов отфильтровать инициализаторы в initializerList найти не удалось.

Остаётся ещё один вариант: каким-то образом указать верную последовательность инициализаторов. Но и тут нас ожидает разочарование: initializerList имеет тип HashMap, который не гарантирует порядок элементов внутри себя!

Это и есть причина непостоянства утечек: если повезёт, то HashMap выдаст Log4jServletContainerInitializer до WSServletContainerInitializer, а если не повезёт, то получим утечку памяти.

Обидно? Да. Есть ли ещё способы избавиться от утечки, кроме того, чтобы писать разработчикам? Да… но только если ты готов перейти на тёмную сторону силы. Я говорю о «временном» решении, в котором можно объявить объект LOGGER нестандартным образом: например, как lazy-loaded singleton. Но давай будем честны с собой: как часто наши временные решения являются действительно временными? Пример подобного кода приводить не буду. На всякий случай.

Выводы

Вывод из всей этой истории прост и неутешителен: универсального решения проблем с такого рода утечками нет. Каждый сервер приложений имеет свои особенности и подходить к ним тоже нужно с разных сторон.

Альтернативным вариантом может быть переход на Spring Boot, но это уже совсем другая история.

Ссылка на проект: https://burov4j.ru/archives/metro-log4j2-memory-leaks.zip.

Статья также была опубликована в журнале “Хакер” в февральском номере: https://xakep.ru/2018/02/05/spring-log4j-memory-leaks-2/

Добавить комментарий

Ваш адрес email не будет опубликован. Обязательные поля помечены *