Поделюсь небольшим трип-репортом о путешествии в увлекательный мир Java
Встретился сегодня с логгерами в Жабе.
Проблема: логгер работает, но ничего не пишет.
Заметка отвечает на вопрос - почему.
0) При старте вижу, что log4j запускается, но использует реализацию NOP, т.е. ничего не делающую. Привычным движением добавляю в мавеновские зависимости джарку бриджа slf4j-log4j... и не происходит ничего. Долго копаюсь в зависимостях, понимаю что конфиг совершенно стандартный, и дело вероятно не в нем. Надо в thinking out of the box, а снаружи коробки у нас только Tomcat, JDK и операционка. Операционка явно не при чем, Томкат после тщательной инспекции - тоже не при чем, остается только JDK. И тут оказывается, что...
1) Крипто Про в своих зависимостях тащит commons-logging. (Понятно что истории, которые начинаются со слова «Крипто Про» ничем хорошим не продолжаются, так что можно вот прямо тут и закрыть эту заметку.) Так вот, Крипта требует положить джарку с commons-logging прямо внутрь JDK/JRE/lib/ext, Карл!. Иначе ничего не работает. То есть, оно зовет логгер прямо из другой джарки внутри jre/lib/ext, поэтому перенести зависимость на commons-logging из JDK в war-файл нельзя, это тупо не заработает. А Другой софт такого подвоха не ждет, и начинает писать логи куда попало. У меня отвалились все логи. Предположение в том, что оно не читает мое log4j.properties (единый файл на весь проект), и теперь нужно заставить его увидеть сей файл.
2). Одна штука все же работает. Это Apache CXF. Копаюсь в потрохах CXF. Там логгер берется не стандартным спосбом-однострочником, а через какой-то LoggerUtils. Открываю, а там адовый метод на три экрана чистейшей лапши из try-catch и if-return'ов. Общий смысл (кажется) - он пытается угадать, какая у нас сейчас система логирования, и подложить костылей. Причем там есть перлы типа обложенного проверками получения значения примитивной интовой переменной, значение которой дальше нигде не используются. Может быть они таким образом расчитывают на интерцепторы, которые перехватят геттер этой переменной (создание такого интерцептора кажется весьма больной идеей, но все таки - там каждая строчка облита кровью жертв, чьи баги фиксят эти костыли). Либо создатели портяны давно уже не совсем понимают ее содержимое, и на всякий случай не трогают. Ах да, комментариев в портяне нет. В общем, запасной вариант на черный день, логирование через кусок магии и jul без конфигов и без ничего у нас есть, но пользоваться им не хочется. Но копание в CXF приводит к мысли, что на самом деле не работает всего лишь переходник с jul на log4j.
3) Дальше иду разбираться как таки заставить работать commons -logging параллельно с log4j и slf4j.
Оказывается, тут надобно впилить log4j и slf4j, и потом поверх два костыля - бридж из jul в slf, и бридж из slf в log4j.
Вместе они начинают работать в такой цепочке: jul -> slf-> log4j. Что само по себе выглядит как чудовище с восемью ногами.
Но они все равно не работают в этой связке. При их включении (сделать котрое можно только зафорсив compile scope на slf - контринтуитивно, учитывая что проблемный класс находится в совсем другой джарке) отваливается даже то, что раньше логировалось через магическую портяну из CXF.
4) Идем разбираться, как же работает log4j. Внутри обнаруживается чудная особенность: он при инициализации берет первый же попавшийся в classpath объект класса чототам-StaticBinder, и использует его как мост до реальной реализации логгера. Причем если этих StaticBinder'ов несколько, то работать будет максимум один (о чем у них честно сообщено в глубинах документации на сайте, но другими словами). Т.е. если захочется, нельзя написать, например, аггрегатор этих StaticBinder'ов (чтобы потом выбирать нужный по ситуации), ибо он вступит в конфликт с аггрегируемым.
5) Дальше смотрим, что делает таки этот Binder. А он делает класслоадер и засасывает туда всякие адпатеры да мосты. Но в конце концов подсасывается класс Hierarchy, который В СТАТИЧЕСКОМ БЛОКЕ, не в конструкторе, инициализирует сам себя. Т.е. например, фиг мы Спрингом (или чем-то еще) по-человечески можем вмешаться в эту вакханалию. Чтобы переопределить этот кусок логики придется копипастой писать свой StaticBinder, беря за основу мост slf4j-log4j, и создавать в нем какую-то другую копипастаную Hierarchy. Вот тебе и ООП. Ну в любом случае, вот и нашли виновника торжества, место которое ломает конфиг.
6) Дальше смотрим, что он делает в секции, может как-то можно подсунуть нужный файл конфига? Ну и видим, что он там есть: там написана некая негибкая лапша, которая вначале ищет В ЛЮБОМ МЕСТЕ класспаса файл log4j.xml, потом если предыдущий файл не найден - опять же в любом месте log4j.properties, а потом смотрит на system property где можно указать оверрайд.
Но мы не можем воспользоваться результатом работы этой лапши:
а) Этот чудный getResources ВСЕГДА находит какой-нибудь log4j.xml внутри ирерахии, т.к. их куча понапихана в библиотеках-зависимостях. Единственный способ не попасть в эту ветку лапши - это указать какой-нибудь оверрайд в system property. Таким образом, в ветку когда оно подцепляет из класспаса log4.properties оно на практике не попадает НИКОГДА. Они сами запутались в своих ifах, что в общем неудивительно...
б) Если вписать system property с путем до файла, оно работает. Но он конструирует его тупо с помощью стандартного класса URL. Т.е. его нельзя указать относительно, например ${catalina.home}/conf/log4j.properties - насколько понимаю, URL не умеет в $-плейсхолдеры (берущие данные из system properties, как можно было бы сделать в случае Спринга). И протокола classpath: по-умолчанию URL не умеет. Да даже если бы умел, оно все равно не подходит, см. следующий пункт.
в) Случай на черный день - вписать system property с абсолютным путем до файла. Но это плохая идея, т.к. повлияет не только на текущее приложение, а вообще на все варки, задеплоенные в Томкате.
Сейчас есть следующие идеи:
z) Покопаться внутри лапши, может туда можно как-то хитро подсунуть относительный путь
x) Попробовать написать свою реализацию протокола classpath: для URL. Но тут возникает проблема в порядке загрузки говнокода. Нужно как-то более-менее гарантировано сделать загрузку этого протокола раньше, чем инициализируется первый логгер (по сути, первый StaticBinder). Иначе есть шанс, что взмах крыльев бабочки в цоде на другой стороне Земляшки разнесет все логироваие к чертям.
c) Написать свой StaticBinder, вызвать там свою Hierarchy, конечно с обильной копипастой из первоисточника чтобы что-нибудь не поломать по дороге, но по пути поправить обнаруженные несправедливости, н-р инициализацию логгера сделать в виде паттерна-стратегия (вместо статического блока)
Вообще, может я чего не понял и просто ламер, всё-таки иногда все эти пирамиды из переходников работают... Интересно, почему... Но я вот тут мимо крокодил, и по крайней мере _выглядят_ все эти пирамиды как адовое рукожопие, какая-то плохо документированная лапша. Склеенная на изоленту (у которой истек срок годности году эдак еще в 1998. Написанная редкими специалистами по PHP, простите - ООП.