LINUX.ORG.RU

Немного о логировании в Java

 , , ,


5

5

Поделюсь небольшим трип-репортом о путешествии в увлекательный мир 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, простите - ООП.

★★★☆☆

Я когда-то на вебсфера проблемы с логгированием и XML-парсингом решал тем, что в настройках веб-приложения указывал, class loading policy last. Фиг его знает, как оно работало, но похожие на твои проблемы решались магически, т.е. библиотеки приложения были в приоритете. Может тебе надо похимичить с этими самыми класслоадерами, чтобы максимально дистанцироваться от того, что загружено в JDK.

Ещё не очень понятно — пробовал ли ты суать jcl-over-slf4j.jar вместо commons-logging. По идее это самое простое решение, которое должно работать.

Legioner ★★★★★ ()
Последнее исправление: Legioner (всего исправлений: 1)

А всё потому что писать нужно на C

EXL ★★★★★ ()
Ответ на: комментарий от EXL

И что там есть чтобы решать проблему логирования, в Си?

stevejobs ★★★☆☆ ()
Ответ на: комментарий от Legioner

пробовал ли ты суать jcl-over-slf4j.jar

        <dependency>
            <groupId>log4j</groupId>
            <artifactId>log4j</artifactId>
            <version>${log4j.version}</version>
        </dependency>

        <dependency>
            <groupId>org.slf4j</groupId>
            <artifactId>slf4j-api</artifactId>
            <version>${slf4j.version}</version>
            <scope>compile</scope>
        </dependency>

        <dependency>
            <groupId>org.slf4j</groupId>
            <artifactId>slf4j-log4j12</artifactId>
            <version>${slf4j.version}</version>
            <scope>compile</scope>
        </dependency>

        <dependency>
            <groupId>org.slf4j</groupId>
            <artifactId>jcl-over-slf4j</artifactId>
            <version>${slf4j.version}</version>
            <scope>compile</scope>
        </dependency>

        <dependency>
            <groupId>org.slf4j</groupId>
            <artifactId>jul-to-slf4j</artifactId>
            <version>${slf4j.version}</version>
            <scope>compile</scope>
        </dependency>

        <!--<dependency>-->
            <!--<groupId>org.apache.logging.log4j</groupId>-->
            <!--<artifactId>log4j-slf4j-impl</artifactId>-->
            <!--<version>2.6.1</version>-->
        <!--</dependency>-->

        <!--<dependency>-->
            <!--<groupId>org.slf4j</groupId>-->
            <!--<artifactId>slf4j-simple</artifactId>-->
            <!--<version>${slf4j.version}</version>-->
        <!--</dependency>-->
stevejobs ★★★☆☆ ()

Хрена у вас там черная магия! Продолжение истории будет?

Radjah ★★★★★ ()

да, логирование в java говно, да виноваты в это разрабы jdk которые сначала ничего не сделали а потом впилили тормознутую хренотень которую починили только к 1.7 или 1.8 точно не помню

subwoofer ★★★★★ ()
Ответ на: комментарий от stevejobs

1) Крипто Про в своих зависимостях тащит commons-logging. (Понятно что истории, которые начинаются со слова «Крипто Про» ничем хорошим не продолжаются, так что можно вот прямо тут и закрыть эту заметку.) Так вот, Крипта требует положить джарку с commons-logging прямо внутрь JDK/JRE/lib/ext, Карл!. Иначе ничего не работает.

Вот в этом месте положить jcl-over-slf4j.jar вместо commons-logging.jar

Legioner ★★★★★ ()

logback пробовал прикручивать? было ощущение, что это самый дубовый логгер.

Deleted ()
Ответ на: комментарий от stevejobs

syslog(3), после чего отстается только сконфигурить по вкусу syslog-ng

annulen ★★★★★ ()
Последнее исправление: annulen (всего исправлений: 1)

Эпичная стена боли :)

Придумай тег, я хочу подписаться %)

Stil ★★★★★ ()

А как эта Крипта сама подключается. Тоже в JDK вгрызается?

spoilt ★★ ()
Ответ на: комментарий от Deleted

Сам логгер норм. Но за его реализацию аппендера к БД нужно убивать. Было время, что больные люди попросили сыпать логами в Postgres. Настройка аппендера крови попила. Потому что даже на ошибку с паролем к базе оно вешало проект, сыпало исключениями, мол драйвер к БД не торт и не поддерживает что-то там очень важное.

spoilt ★★ ()

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

anonymous ()

Тот случай, когда по заголовку топика понял кто его написал))))

ii8_ ★★★★ ()

Увлекательно. Заведи себе бложек, или тег. Ну и мрак в этом вашем кровавом энтерпрайзе.

feofan ★★★★★ ()

Аж руки захотелось помыть.

anonymous ()
Ответ на: комментарий от annulen

в смысле, не сислог, а jounrald с публикацией в сислог? И чем это отличается от slf4j? =) Те же миллионы переходников, только в случае systemd они еще и прибиты гвоздями к коду системд (или там можно расширять на ходу, без пересборки из исходников?) Олсо, как насчет кроссплатформенности - вот ты на Windows Server 2012 какую реализацию сислога используешь?

кстати, жаба, в смысле log4j тоже умеет в сислог: https://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/net/SyslogAppen...

stevejobs ★★★☆☆ ()
Последнее исправление: stevejobs (всего исправлений: 1)
Ответ на: комментарий от spoilt

Тоже в JDK вгрызается?

Именн. sudo bash ./install.sh /путь/до/jdk. Причем этот скрипт насктолько наколенке написан, что некоторые зависимости он из своего же дистрибутива копировать не умеет - нужно идти и копировать их внутрь ждк прям руками

stevejobs ★★★☆☆ ()
Ответ на: комментарий от Stil

Придумай тег, я хочу подписаться %)

www.linux.org.ru/tag/стенаболи - для стен боли
www.linux.org.ru/tag/java тормозит - для остального про java

feofan

Заведи себе бложек

https://www.facebook.com/olegchir/posts/1145096438846695
http://users.livejournal.com/--hedin/802536.html

stevejobs ★★★☆☆ ()
Последнее исправление: stevejobs (всего исправлений: 4)

У меня три вопроса:

1) Обязательно ли ставить КриптоПро с использованием системной JDK?

2) Обязательно ли пускать ваш софт с использованием той же JDK, что и КриптоПро?

3) Где живут авторы КриптоПро?

TheKnight ★★ ()
Последнее исправление: TheKnight (всего исправлений: 1)
Ответ на: комментарий от stevejobs

в смысле, не сислог, а jounrald с публикацией в сислог?

не трогай каку. На крайняк у syslog-ng есть своя либа, позволяющая отправлять syslog-сообщения с метаданными безо всяких системГ

Олсо, как насчет кроссплатформенности - вот ты на Windows Server 2012 какую реализацию сислога используешь?

Ну так все логично, виндузятники страдают :)

annulen ★★★★★ ()

Угадал автора по первому предложению.

Проблем и баттхерта от логгеров пока не испытывал.

Ну и да, тс, вот ты и нашел себе, чем заняться.

cdshines ★★★★ ()
Ответ на: комментарий от TheKnight

Legioner

Вот в этом месте положить jcl-over-slf4j.jar вместо commons-logging.jar

Основная и единственная ценность крипты - в сертификации от ФСБшников. Если начать копаться в её зависимостях и что-то там подменять, она резко перестанет быть сертифицированной и такой софт не пропустят. Более того, админам и так не нравится идея патчить JDK, а уж за патч на патч они будут есть мой мозг до конца жизни)

TheKnight

1) нет. У нас куча разных JDK под разные нужды, и ни одна из них не явлется системной. Под виндой так и вообще нет такого понятия)

2) да, обязательно, других официальных/сертифицированных способов нет.

3) Вообще, может Крипта не так уж и виновата, и вопрос решается как-то легко, и это я чайник. Может быть там еще от кого-то мусор в JDK остался. Единственное свидетельство в мою защиту - то, что на официальных форумах тоже есть люди с аналогичной проблемой

annulen

ну ага, а админы продакшен-серверов, которые будут разворачивать твой софт, конечно погладят тебя по головке за «безо всяких системГ». Учитывая что все дистрибутивы уже на нем, и админы соответственно поменяли свой workflow на него. Молодые админы уже и не помнят времен без системд =)

cdshines

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

stevejobs ★★★☆☆ ()
Ответ на: комментарий от stevejobs

Я хз, у нас на прдакшен-серверах развернут syslog-ng и все довольны. Будет ли syslog(3) ходить через systemd или напрямую через сокет - строго говоря пофиг, разница в произвоительности копеечная и находится вне приложения. А адимны должны заботиться о том, чтобы приложение работало, а не о том, чтобы оно максимально интегрировалось в системГ

annulen ★★★★★ ()

требует положить джарку с commons-logging прямо внутрь JDK/JRE/lib/ext, Карл!

вангую у них до сих пор минимальное требование 1.4.2 там по другому работать не будет.

commons-logging

Библиотека замечательная при условии, что её все используют, но так как опенсорс строем не ходит, то каждый дев. своим долго считает поставить зависимость от своего любимого логера. Что порождает зоопарк и понятную попаболь. Ты не поймал самый клёвый случай - это самописный логгер, слава яйцам уже практически исчезающий вид.

vtVitus ★★★★★ ()
Ответ на: комментарий от vtVitus

Ты не поймал самый клёвый случай - это самописный логгер, слава яйцам уже практически исчезающий вид.

Писал в своем приложении отдельно логгер. Гадил в консоль и в файл а потом еще и убивал файл если больше 100 КБ. 2012 был на дворе еще.

spoilt ★★ ()
Последнее исправление: spoilt (всего исправлений: 1)
Ответ на: комментарий от stevejobs

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

cdshines ★★★★ ()
Ответ на: комментарий от cdshines

А что ты понимаешь под concurrency в логгере?

Я так понимаю, concurrency возникает, когда у нас имеется shared mutable state, и бывает двух основных типов: когда это часть предметной области (и она хорошо моделируется готовыми технологиями внутри языка и рантайма), или когда это хакерский вид оптимизации

В логгере всей предметной области - брать строчку и слать её в аппендер, который будет аппендить куда-нибудь типа файла или бота в телеграме. Причем этот аппендер - это даже не совсем mutable state, потому что к нему только добавляются новые записи, а старые уже добавленные - более чем immutable. Т.е. там нужна конкурентная очередь и всё, которая у нас уже внезапно есть, ConcurrentLinkedQueue или LinkedTransferQueue (вот как всегда нечестное сравнение перфоманса: https://gist.github.com/normanmaurer/3180812). Продюсеры - это объекты класса Log, их много. Очередь одна. Косумер - аппендер в файл или что-то еще - тоже один (никто ведь не хочет параллельно писать в файл, да? :). То есть никакой проблемы нет вообще, нечего решать.

Например, в log4j v1 есть всякие проблемы с конкаренси, но это потому, что только дибил в 2016 году будет устраивать «оптимизацию» инициализацией класса в статическом блоке вместо инит-метода, переиспользовать один и тот же класс в разных ролях итп. Никто больше не экономит на глубине структуры классов и количестве warmum объектов, считается вполне нормальным использовать иммутабельность когда данные не гигантские, итп. Может это как-то связано с тем, что log4j появился в 2001 году, когда вместо компьютеров все еще были кофеварки, а программисты на java писали на ней консольные утилиты. Сейчас в нормальном приложении один только Spring (DI, Boot, AOP, etc) будет вармапиться минимум несколько секунд, описанная выше оптимизация инициализации будет как капля в море, а дизастер она может притащить с собой некислый - поэтому просто не нужна.

Вот как-то так пока вижу.

А ты что имел в виду?

stevejobs ★★★☆☆ ()
Ответ на: комментарий от cdshines

кстати, а как правильно делать многопоточную запись в файл?

stevejobs ★★★☆☆ ()
Последнее исправление: stevejobs (всего исправлений: 1)
Ответ на: комментарий от stevejobs

Я почему-то тогда решил, что ты хочешь написать все с нуля. Аналог CLQ/LTQ в т.ч., ну или что там. Получить результаты, сравнимые с log4j2 с disruptor - фантастика.

В файл же пишет отдельно назначенный тред?

cdshines ★★★★ ()

Стиви, так долго с java работаешь, и только на это наткнулся.

Если билдишь проект с мавен - берешь effective pom, находишь все бриджи slf4j-to-shit и выпиливаешь их через dependency exclude(скажем спасибо разрабам что бекенд логгера описывают не как optional).

Помним, что например activemq-all - это уберджар, со всем зависимостями, включая бекенды логгеров. Ими не пользуемся, берем нормальные, типа activemq-core.

Потом добавляем logback. ИМХО, он самый удобный и легко расширяется. Иногда проще написать кастомный аппендер, чем долбиться чужими решениями: «универсальными, но нам не подходит»

Видишь как в catalina.log один из логгеров пишет мимо slf4j. Ищешь этот бекенд, и пихаеш в зависимости logger-over-slf4j мост. И так пока твоё приложение не начнет писать логи как тебе нравится

anonymous ()
Ответ на: комментарий от stevejobs

А толку, всеравно сискол один. В лучшем случае через nio.channel async write проталкивать. Но придется синхронизироваться на tail-offset в файле. Памяти жрать меньше не будет. Производительность записи, если дисховое хранилище - это не СХД, тоже сомнительна. Да и опять таки, если СХД - он сам распараллелит запись.

anonymous ()

Классная наверно история, но я не осилил настолько огромную простыню.
А по логерам: у меня студенты легко справляются с настройкой и не жалуются, да и на работе всё отлично логируется.

Xunnu ★★ ()
Вы не можете добавлять комментарии в эту тему. Тема перемещена в архив.