Java Logging: история кошмара

Вступление

Тернист и извилист путь Java-платформы к правильному способу записи строчек в лог-файлы. История logging в Java довольно познавательна в плане изучения особенностей Open Source, в том числе его взаимодействия с корпорациями и единичными программистами. Я собираюсь рассказать столько, сколько возможно, об истории развития Java logging, а также о том, к чему все пришло и как жить дальше. Мой анализ ситуации будет довольно субъективен про причине того, что logging — это всегда дело вкуса, а вкусы у меня сформировались свои, взрослые. Я думаю, что это будет познавательно не сколько в плане каких-то технических особенностей всего зоопарка logging frameworks, а в плане политики и психологии разработчиков в модели Open Source.

Начало

Понятно, что любая logging-библиотека должна позволять как минимум печатать строку на консоль/в лог-файл.

В начале был, конечно System.err.println. Кроме того, первая версия Servlet API имела в составе функцию log (впрочем, довольно примитивную).

Одним из вариантов более продвинутых решений в 1999 году был проект Avalon (и подпроекты, которые назывались Excalibur и Fortress), который помимо сервисов DI предлагал интерфейс LogEnabled. В компонент, который объявлял себя LogEnabled, инжектировался (я применяю это слово вместо «инъектировался», чтобы подчеркнуть его связь с DI) объект типа Logger, куда можно было писать: а) строки б) exceptions. Подход этот по тем временам казался свежим и новаторским, однако с современной точки зрения это чистой воды идиотизм и over-engineering. Использовать DI для логгирования никакого смысла нет, и статический экземпляр этого самого Logger вполне бы всех устроил. В Avalon же приходилось думать, куда этот проклятый Logger сохранить и что же делать, если класс не использует DI (т.е. не управляется контейнером), а логгировать в нем очень хочется.

Приблизительно в 1999 появляется библиотека нового поколения — log4j. Прототип библиотеки был разработан IBM (еще в эпоху, когда голубой гигант пытался втиснуть Java в OS/2), затем эстафету подхватил ASF. Продукт был уже гораздо более продуманный и обкатанный на реальных нуждах. Вообще надо сказать, что серверным приложениям на Java к тому моменту исполнилось всего где-то годик, а логгирование всегда было востребовано именно на сервере. За это время Java-сообщество начало постепенно понимать, что и как им нужно.

log4j разделил понятие логгера или категории (т.е. область приложения, которая хочет записать в лог), собственно записи в лог, которую осуществляют так называемые appenders, и форматирования записей (layout). Конфигурация log4j определяет, какие appenders к каким категориям прикрепляются и сообщения какого уровня (log level) попадают в каждый appender.

Краеугольный камень log4j — это иерархичность категорий. Например, можно логгировать все сообщения из org.hibernate и заглушить всё из org.hibernate.type. Через некоторое время де-факто установилась практика соответствия иерахии категорий и иерархии пакетов в приложении.

Иерархия категорий позволяет довольно эффективно отсекать лишние сообщения, поэтому log4j работал чрезвычайно шустро. Кстати, принципиальной для логгеров является не столько скорость записи, сколько скорость фильтрации ненужного (а ненужного обычно более 90%) и форматирование.

Принципы, заложенные в log4j, были довольно удачно портированы на другие языки: log4cxx, log4net (и свежий детеныш — log4php). Стандартный пакет logging в Python 2.x представляет собой переработанный log4j (с небольшой добавкой других библиотек).

Итак, резюмируем. Удачная архитектура, понятная схема конфигурирования, принцип fail-safe — почему бы не включить такую замечательную библиотеку в состав платформы?

Java Logging API

На деле все получилось странно. IBM, в недрах которой возник log4j, оказалась довольно шустрой в вопросах формирования нового JSR47 (Java Logging API). В частности, ответственный за JSR47 товарищ Graham Hamilton решил взять за основу не log4j, а оригинальный IBM logging toolkit. Причем logging toolkit был использован на полную катушку: совпадали не только имена всех основных классов, но и их реализации; код старались допиливать как можно меньше, видимо, чтобы успеть к очередному релизу платформы. Впрочем, концептуально это было очень похоже на log4j, только вместо appenders это называлось handlers, а вместо layout был formatter.

Поскольку основное назначение JSR47 — определять API, а не реализацию, доступных (по умолчанию в платформе) средств вывода было всего 4 (в log4j более 10), а средства форматирования были настолько бедны, что практически сразу приходилось делать свои formatter-ы, поскольку готовых не хватало. JSR47 предлагал использовать конфигурацию в виде .properties, причем в скобках отмечалось, что в файле можно описать не все. Таким образом, при усложнении конфигурации программист неожиданно обнаруживал, что опять требуется писать код, т.к. в виде .properties его конфигурация нереализуема.

Нельзя сказать, чтобы JSR47 проигрывал в производительности. Местами он обгонял log4j за счет поддержания в памяти специального представления своей конфигурации (что, кстати, одновременно усложняло эту самую конфигурацию). Однако, как выяснилось, JSR47 в обязательном порядке собирал так называемую Caller Information, то бишь «откуда логгируется данное сообщение». Получение Caller Information — операция довольно дорогостоящая, протекает она с использованием Native-кода. Опытные дяди из log4j это знали, поэтому предоставляли эту возможность с оговоркой «лучше не включайте».

Разработчики log4j выступили с открытой петицией, где потребовали «снять JSR47 с конвейера», пока он еще не попал в состав платформы. Петицию подписали более 100 человек… Однако было уже поздно. Следующий релиз JDK был утвержден и платформа понеслась в будущее с рудиментарным java.util.logging, или сокращенно JUL. Новый логгинг был настолько неразвит и неудобен, что использовать его решились только в нескольких серверах приложений (среди них Resin и Jetty). Sun, впрочем, отреагировала на петицию и большинство крупных проблем оригинального JSR47 постепенно были устранены. Тем не менее, эти манипуляции походили скорее на установку подпорок к деревянному мосту, которые ну никак не сделают этот мост железобетонным. Разработчики log4j сделали реверанс в сторону Sun, заметив, однако, что степень кривизны JUL все еще довольно высока. Помимо всего прочего, лицензия JDK 1.4 не позволяла использовать log4j в качестве реализации JUL. Последний поезд для log4j ушел.

Не будучи способным поддержать большое число лог-писателей (т.е. handlers), JUL выпендрился, определив неимоверное число уровней логгирования. Например, для отладочных сообщений существовало аж 3 уровня — FINE, FINER и FINEST. Видя всё это, разработчики зачастую совершенно не понимали, какой же из трех уровней, чёрт возьми, надо использовать.

Java-сообщество было совершенно дезориентировано появлением «стандартного» логгинга параллельно с популярным, стабильным и развивающимся log4j. Никто не понимал, кто из них двоих жилец. Нередки были ситуации, когда в проекте было собрано несколько библиотек, каждая из которых использовала свой логгинг и свои настройки, записывая совершенно вразнобой свои лог-файлы.

Разумеется, сообщество попыталось исправить эту проблему. Началась оберточная эпидемия. Или, я бы даже сказал, пандемия.

Wrapper Hell

Когда вы подключаете несколько библиотек и пытаетесь соединить их логи в одно целое (а код модифицировать нельзя), это будет называться Adapter. Были написаны переходники из JUL в log4j и наоборот. К сожалению, переходники по функционалу являются «наименьшим общим кратным». Даже когда в log4j появилась поддержка контекста (NDC и MDC), при переливании в JUL она терялась. Хуже того, JUL работал только начиная с JDK 1.4, в то время как неимоверное количество enterprise-приложений все еще сидело на 1.3. В итоге, сообщество стало одержимо идеей создания «общего стандарта де-факто», который бы все стали дружно употреблять и который работал всегда и везде.

Приблизительно в 2002 из группы Jakarta выделился проект под названием commons-logging (JCL = Jakarta Commons Logging). Фактически это была обертка всех существующих на тот момент средств логгинга. Предлагалось писать приложения так, что они обращались к обертке (интерфейсу под названием Log), которая выбирала «подходящую» систему логгинга и сама к ней подключалась. Обертка была бедновата фунционально и никаких дополнений к существующим средствам логгинга не вносила.

Как же автоматически выбиралась подходящая система логгирования? А вот это самое интересное. Во-первых, можно было задать ее явным образом размещением специального commons-logging.properties-файла где-нибудь в CLASSPATH. Во-вторых, через системное свойство (что, очевидно, никто делать не будет). В-третьих, если где-то в CLASSPATH обнаруживался log4j, то он автоматически задействовался. Таким же методом разыскивались реализации всех остальных библиотек, всегда подключалась первая найденная.

Красиво! Ну то есть было бы красиво, если бы весь софт в мире использовал бы commons-logging. Тогда можно было спокойно собрать JARы, положить в сервер приложений, а там уж JCL подхватит логгинг данного сервера приложений и вуаля!

На самом деле, как выяснилось, куча софта использует обычно «любимый логгинг своего разработчика». Это означает, что совершенно произвольная библиотека может в виде зависимости подтянуть, например, log4j, который таким образом попадет в CLASSPATH и неожиданно переключит JCL на использование log4j. Еще хуже с commons-logging.properties. Если какой-нибудь деятель додумывался запихнуть его в свой JAR, то при подключении этого JAR-а — сами понимаете — пиши пропало. Особую пикантность ситуации придавало то, что совершенно непонятно было, из какого именно JAR-а приехала инфекция. Иногда помогал перебор всех JAR-ов в алфавитном порядке. Иногда бубен.

Полная непредсказуемость выбора логгинга оказалась главной и очень веселой особенностью JCL. Группа log4j разразилась гневной статьей Think again before adopting the commons-logging API, где предлагала остановить эпидемию и сосредоточить внимание на доработке существующего решения — log4j.

К сожалению, было уже поздно. С подачи Jakarta на commons-logging были переведены сотни, а затем тысячи библиотек. В их числе были Hibernate, Spring, Tomcat. После чего многочисленных пользователей этих библиотек захлестнула волна проблем, в целом описываемых как ClassLoader hell. В серверах приложений используется довольно сложная иерархия ClassLoader-ов, причем зачастую с серьезными отклонениями от стандарта J2EE. В этих условиях иногда JCL инициализируется дважды, причем неправильно, приводя к совершенно мистическим stack traces, не позволяющим даже заподозрить, что проблема в лог-обертке.

Почему, собственно говоря, Open Source сработал таким странным образом, породив на свет данное извращение? Почему разработчики не решились просто так взять и использовать другой зрелый и популярный Open Source продукт — log4j? Дело здесь, возможно, в некоторой инертности сообщества, привыкшего идти на поводу либо у ASF (а группа Jakarta, породившая данный кошмар, есть часть ASF), либо у Sun. Как только образуется критическая масса проектов, использующих JCL, все остальные (и не самые глупые люди, так ведь, Gavin King?) начинают использовать JCL (ибо Apache — это круто!). Это в целом напоминает броуновское движение, где такие бренды как Apache или Sun способны создавать области низкого давления, куда устремляются миллионы разработчиков. В случае JCL «история успеха» описана в блоге Rod Waldhoff (один из разработчиков так называемых Jakarta Commons) в 2003 году.

Новый виток прогресса

Итак, где-то на 2004 год имеем в комплекте:

1. Стабильный и функционально развитый log4j
2. Унылый java.util.logging
3. Проблемный commons-logging
4. Несколько мелких логгеров, недостойных упоминания

Отметим, что в проекте log4j в это время преобладали консервативные настроения. Особое внимание уделялось вопросу совместимости со старыми JDK. Вроде бы начинается разработка новой ветки log4j — 1.3.x. Эта версия — своего рода компромиссное решение: да, хочется новый функционал, да, хочется поддерживать обратную совместимость, да, попробуем угодить и нашим и вашим. А тем временем на подходе JDK 1.5 с varargs, JMX extensions и кучей других подарков. В команде log4j началось брожение умов. Отпочковывается ветка 2.x — несовместимая с основной веткой 1.2.x и созданная специально для JDK 1.5. Java-сообщество изнывает в нетерпении. Происходит вроде бы как что-то. Но что именно, не понять — log4j 2.0 по-прежнему остается недостижимой альфой, log4j 1.3 дико глюкав и не обеспечивает обещанной drop-in совместимости. И только ветка 1.2 по-прежнему стабильна и жива-здорова, прыгнув за несколько лет — внимание! — с версии 1.2.6 до 1.2.12.

Где-то в 2006 году один из отцов-основателей log4j — Ceki Gülcü — решает выйти из стремительно тухнущей команды. Так появляется на свет очередная «обертка всего» под названием SLF4J (Simple Logging Facade for Java). Теперь это обертка вокруг: log4j, JUL, commons-logging и нового логгера под названием logback. Как видно, прогресс быстро дошел до стадии «обертка вокруг обертки». Нетрудно спрогнозировать, что по той же схеме число обертываемых библиотек будет расти как факториал. Однако SLF4J предлагает и другие прочие выверты. Это специальные binary-переходники: из log4j в SLF4J, из commons-logging в SLF4J и тому подобное. Делаются такие переходники для кода, исходники которого недоступны; при этом они должны подменить оригинальные JAR-ы лог-библиотек. Не берусь представить себе, какая каша при этом образуется, но если очень хочется, то можно и так.

При всей моей ненависти к оберткам, положа руку на сердце, SLF4J — хорошо сделанный продукт. Были учтены все недостатки предшественников. Например, вместо шаманских плясок с поиском классов в CLASSPATH придумана более надежная схема. Теперь вся обертка делится на две части — API (который используется приложениями) и Реализация, которая представлена отдельными JAR-файлами для каждого вида логгирования (например, slf4j-log4j12.jar, slf4j-jdk14.jar и т.д.). Теперь достаточно только подключить к проекту нужный файл Реализации, после чего — опа! весь код проекта и все используемые библиотеки (при условии, что они обращаются к SLF4J API) будут логгировать в нужном направлении.

Функционально SLF4J поддерживал все современные навороты типа NDC и MDC. Помимо собственно обертывания вызовов, SLF4J предлагал небольшой, но полезный бонус при форматировании строк. Бонус тут в следующем. В коде часто приходится печатать конструкции вида:

log.debug("User " + user + " connected from " + request.getRemoteAddr());

Помимо собственно печати строки, тут неявно произойдет преобразование user.toString() с последующей конкатенацией строк. Все бы ничего. В отладочном режиме скорость выполнения нас не очень волнует. Однако даже если мы выставим уровень, скажем, в INFO, окажется, что конструирование строки все равно будет происходить! Никаких чудес: строка конструируется перед вызовом log.debug, поэтому log4j не имеет возможности как-то это контролировать. Если представить, что этот log.debug размещен в каком-то критическом внутреннем цикле… в общем, так жить нельзя. Разработчики log4j предложили обрамлять отладочный код так:

if (log.isDebugEnabled()) {
    log.debug("User " + user + " connected from " + request.getRemoteAddr());
}

Нехорошо получается. По идее все эти проблемы должна брать на себя сама logging-библиотека. Эта проблема стала просто ахиллесовой пятой log4j. Разработчики вяло реагировали на пинки, рассказывая, что в logging-вызовы теперь можно еще добавить объект (ровно один!), да еще описать, как этот объект будет записан в лог с помощью интерфейса ObjectRenderer. По большому счету, все это были отмазки и полумеры.

SLF4J не был стиснут рамками совместимости со старыми версиями JDK и API, поэтому с ходу предложил более изящное решение:

    log.debug("User {} connected from {}", user, request.getRemoteAddr());

В общем-то, все просто. В данной строке {} — это ссылки на параметры, которые передаются отдельно. Преобразование параметров в строку и окончательное форматирование лог-записи происходит только при установленном уровне DEBUG. Параметров можно передавать много. Работает! Не надо писать обрамляющий if и прочую тупость!

В скобках надо отметить, что данную возможность также совершенно неожиданно реализовал язык Groovy, где есть понятие GString, т.е. строка вида

"User ${user} connected from ${request.getRemoteAddr()}"

, которая неявно связана с несколькими контекстными переменными (здесь это user, request), причем вычисление строки происходит отложенным образом. Это очень удобно для таких лог-библиотек как log4j — можно получить на вход GString, а затем или выбросить его без вычисления, или все-таки преобразовать в нормальную (статическую) строку — String.

Короче говоря, SLF4J был сделан грамотно, с заделом на будущее. Это вызвало серьезный рост его популярности среди сообщества: сейчас SLF4J используют такие значимые проекты, как Jetty, Hibernate, Mina, Geronimo, Mule, Wicket, Nexus… в общем, практически все неудачники, зависшие в свое время на commons-logging, перешли на SLF4J. Интересно, что мешало усовершенствовать commons-logging до нужного состояния много лет назад? Но таковы реалии Open Source — развитие софта в нем происходит скорее революционно, чем эволюционно.

Одновременно с SLF4J был подан к столу совершенно новый логгер — Logback. Он был сделан человеком, который на логгировании собаку съел, и на поверку действительно оказался хорошим продуктом. Logback был изначально заточен под JDK 1.5+, одним махом избавившись от всех старческих болезней обратной совместимости, свойственных проекту log4j. А это значит — varargs, java.util.concurrent и прочие прелести. Например, за счет встроенной системы runtime-фильтрации можно менять уровень логгирования в зависимости от пользовательской сессии, разбрасывать пользователей по разным лог-файлам и прочее, прочее.

Я подкину горчички в идиллию, нарисованную автором. Большинство этих возможностей можно реализовать в виде дополнительных appender-ов к log4j. Придется искривить и подпилить конфигурацию, это сложнее, но — факт, что переходить для этого на новый логгер не_обязательно. Таким образом, все рекламируемые Logback фишки — удобные, но не уникальные.

Что касается сообщества, то оно к Logback относится с осторожностью. Во-первых, за несколько лет он добрался до версии 0.9.x, а это пугает некоторых программеров. Во-вторых, Logback не находится ни под зонтиком Apache, ни в области действия Sun. Это смущает людей щепетильных. В-третьих, автору надо кушать, поэтому за некоторые довески к Logback и поддержку он требует денег. Это иногда отпугивает студентов. Помимо всего прочего, Logback имеет довольно сложную двойную лицензию (LGPL/EPL), в то время как log4j — универсальную лицензию Apache. Для библиотек и вообще redistributable софта лицензирование является очень тонким моментом.

По большому счету, Logback на сегодняшний день — вершина эволюции. Помимо Logback появилось уже с десяток новых logging-библиотек, но с большой вероятностью ни одна из них не выживет. Подводя итоги, ситуация на данный момент следующая:

• log4j — используют подсевшие на него изначально и не видящие необходимости перехода.
• JUL — тихо умирающий стандарт. Все, кто изначально пытался его использовать, переезжают на Logback.
• commons-logging — обычно задействован в legacy-библиотеках, которые очень боятся причинить неудобства пользователем, переехав на что-нибудь получше.
• SLF4J — очень популярен в библиотеках. Многие переехали на него, не выдержав ужасов commons-logging
• Logback — обычно современные high-performance серверы, которых не устраивает log4j.

Я уже говорил, что Open Source сообщество имеет тенденцию стекаться к «центрам тяжести». Сейчас таким центром тяжести выступает скорее SLF4J в силу «универсальности». Относительная популярность SLF4J в какой-то степени гарантирует от появления новых оберток. Число проектов, использующих SLF4J, уже является достаточным для накопления «критической массы». У Logback (того же автора, заметьте) такой критической массы нет. (Кстати, log4j по прежнему обещает нам золотые горы и версию 2.0, однако воз и ныне там.) Думаю, если Logback усмирит свою гордыню и двинется в Apache, его позиции сильно улучшатся.

Заключение

Интересно посмотреть на историю вопроса под углом психологии программистов. Ведь в принципе всё это спиральное (и вроде как прогрессирующее!) движение — бесконечный «reinvent the wheel». То есть из двух вариантов «доработать существующее» и «сделать свое» всегда выбирался второй. Поэтому ни один из упомянутых проектов не выбился в безусловные лидеры (в те самые стандарты «де-факто»). Вместо этого разработчики были в разное время «нашинкованы» на разные проекты и действовали раздельно, вместо того, чтобы действовать сообща. Хотя не факт, что все авторы смогли бы работать в одной упряжке. Тут действовали и политические моменты (вспомним, как Graham Hamilton любил IBM), и просто банальные ссоры в команде. Стремление же участников Jakarta Commons обеспечить сообществу «свободу выбора» вообще обернулось для сообщества длительной «эпидемией оберток».

В общем-то, все эти пороки типичны для открытого сообщества. Эта более чем 10-летняя история также показывает, насколько ошибочно распространенное сейчас мнение, что Sun как будто бы что-то решало в Java-сообществе. Мы видим, что многие вещи происходили вопреки Sun и независимо от Sun. Одним словом, интересно, как оно пойдет дальше. В одном я уверен — проекты приходят и уходят, люди не меняются :)