log4j2 с pax-logging: нельзя использовать значения из StructuredDataMessage

Я использую pax-logging-api вместе с pax-logging-log4j2 для ведения журнала из моих пакетов OSGi. Я хотел бы использовать Log4J2 StructuredDataMessage (используя EventLogger) для записи некоторых сообщений в базу данных. Однако я не могу прочитать значения, которые я ввел в StructuredDataMessage, из приложений при использовании Pax Logging.

Следующее работает в проекте, отличном от OSGi, с непосредственным использованием библиотек Log4J2:

log4j2.properties:

appender.console.type = Console
appender.console.name = STDOUT
appender.console.layout.type = PatternLayout
appender.console.layout.pattern = %m%n

appender.event.type = Console
appender.event.name = event
appender.event.layout.type = PatternLayout
appender.event.layout.pattern = %marker ${sd:id} ${sd:testKey} %n    %m%n

rootLogger.level = debug
rootLogger.appenderRef.console.ref = STDOUT

logger.event.name = EventLogger
logger.event.level = debug
logger.event.appenderRef.console.ref = event
logger.event.additivity = false

Test.java:

public class Test {

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

    public static void main(String[] args) {
        StructuredDataMessage msg = new StructuredDataMessage("1", "message", "event");
        msg.put("testKey", "testValue");

        LOGGER.info(msg);
        EventLogger.logEvent(msg);
    }
}

Вывод:

 1 testValue event [1 testKey="testValue"] message
EVENT 1 testValue 
    event [1 testKey="testValue"] message

Обратите внимание, что приложение event правильно разыменовало ключи sd из сообщения StructuredDataMessage.

Однако следующее не работает в OSGi с pax-logging:

org.ops4j.pax.logging.cfg:

log4j2.appender.console.type = Console
log4j2.appender.console.name = STDOUT
log4j2.appender.console.layout.type = PatternLayout
log4j2.appender.console.layout.pattern = %m%n

log4j2.appender.event.type = Console
log4j2.appender.event.name = event
log4j2.appender.event.layout.type = PatternLayout
log4j2.appender.event.layout.pattern = %marker \$\\\{sd:id\} \$\\\{sd:testKey\} %n    %m%n

log4j2.rootLogger.level = debug
log4j2.rootLogger.appenderRef.console.ref = STDOUT

log4j2.logger.event.name = EventLogger
log4j2.logger.event.level = debug
log4j2.logger.event.appenderRef.console.ref = event
log4j2.logger.event.additivity = false

Test.java:

public class Test implements BundleActivator {

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

    @Override
    public void start(BundleContext context) throws Exception {
        StructuredDataMessage msg = new StructuredDataMessage("1", "message", "event");
        msg.put("testKey", "testValue");

        LOGGER.info(msg);
        EventLogger.logEvent(msg, Level.INFO);
    }

    @Override
    public void stop(BundleContext context) throws Exception {
    }
}

Вывод:

event [1 testKey="testValue"] message
EVENT ${sd:id} ${sd:testKey}
    event [1 testKey="testValue"] message

Есть ли способ заставить это работать в pax-logging? Я могу получить доступ к значениям из MDC, используя \$\\\{ctx:key\}, когда это применимо, поэтому я предполагаю, что синтаксис аналогичен. Я также пробовал использовать поисковые запросы в шаблонах для RoutingAppender, FileAppender и т.д., но безрезультатно.

Заранее спасибо!

Изменить: я использую последнюю версию pax-logging-api и pax-logging-log4j2 (1.11.3)


person roadkill    schedule 14.11.2019    source источник
comment
Напишите, пожалуйста, какую версию pax-logging вы используете, и я постараюсь воспроизвести.   -  person Grzegorz Grzybek    schedule 14.11.2019
comment
@GrzegorzGrzybek спасибо! Пользуюсь версией 1.11.3.   -  person roadkill    schedule 14.11.2019


Ответы (1)


Хорошо, это еще не окончательный ответ - просто комментарий слишком короткий, чтобы описать, что происходит.

Трассировка стека с вашим вызовом:

"pipe-restart 238@10666" prio=5 tid=0xc3 nid=NA runnable
  java.lang.Thread.State: RUNNABLE
      at org.ops4j.pax.logging.log4j2.internal.PaxLoggerImpl.doLog0(PaxLoggerImpl.java:354)
      at org.ops4j.pax.logging.log4j2.internal.PaxLoggerImpl.doLog(PaxLoggerImpl.java:337)
      at org.ops4j.pax.logging.log4j2.internal.PaxLoggerImpl.inform(PaxLoggerImpl.java:233)
      at org.ops4j.pax.logging.internal.TrackingLogger.inform(TrackingLogger.java:209)
      at org.ops4j.pax.logging.log4jv2.Log4jv2Logger.logMessage(Log4jv2Logger.java:162)
      at org.apache.logging.log4j.spi.AbstractLogger.log(AbstractLogger.java:2102)
      at org.apache.logging.log4j.spi.AbstractLogger.tryLogMessage(AbstractLogger.java:2190)
      at org.apache.logging.log4j.spi.AbstractLogger.logMessageTrackRecursion(AbstractLogger.java:2144)
      at org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2127)
      at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1828)
      at org.apache.logging.log4j.EventLogger.logEvent(EventLogger.java:56)
      at grgr.test.ActivatorLogging.start(ActivatorLogging.java:39)
...

org.ops4j.pax.logging.log4jv2.Log4jv2Logger.logMessage() - это мост между фасадом журналирования и серверной частью журналирования.

Помните - с pax-logging вы можете, скажем, использовать Commons Logging фасад с Log4J1 backend или Log4j2 фасадом (и это то, что вы повторное выполнение), например, с помощью Logback backend.

Вот почему org.ops4j.pax.logging.log4jv2.Log4jv2Logger.logMessage() делает это:

} else if (level.intLevel() >= Level.INFO.intLevel()) {
    m_delegate.inform(paxMarker, message.getFormattedMessage(), t, fqcn);

и ваше структурированное сообщение изменится на String event [1 testKey="testValue"] message.

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

Эти 3 строки:

  at org.ops4j.pax.logging.log4j2.internal.PaxLoggerImpl.inform(PaxLoggerImpl.java:233)
  at org.ops4j.pax.logging.internal.TrackingLogger.inform(TrackingLogger.java:209)
  at org.ops4j.pax.logging.log4jv2.Log4jv2Logger.logMessage(Log4jv2Logger.java:162)

выполните пересечение от pax-logging-api (фасад) через TrackingLogger (мост) до pax-logging-log4j2 (backend), теряя структурированную информацию между ними.

Я создал https://ops4j1.jira.com/browse/PAXLOGGING-302 И надеюсь в ближайшее время что-нибудь с этим поделать.

РЕДАКТИРОВАТЬ1

Ключ в том, что в org.apache.logging.log4j.core.lookup.StructuredDataLookup#lookup() это условие выполняется:

if (event == null || !(event.getMessage() instanceof StructuredDataMessage)) {
    return null;
}

РЕДАКТИРОВАТЬ2

Я только что исправил https://ops4j1.jira.com/browse/PAXLOGGING-302 и этот тест доказывает, что это работает:

Logger logger = LogManager.getLogger("my.logger");

logger.info(new StructuredDataMessage("1", "hello!", "typeX").with("key1", "sd1"));
logger.info(new StringMapMessage().with("key1", "map1"));

List<String> lines = readLines();
assertTrue(lines.contains("my.logger/org.ops4j.pax.logging.it.Log4J2MessagesIntegrationTest typeX/sd1 [INFO] typeX [1 key1=\"sd1\"] hello!"));
assertTrue(lines.contains("my.logger/org.ops4j.pax.logging.it.Log4J2MessagesIntegrationTest ${sd:type}/map1 [INFO] key1=\"map1\""));

конфигурация такая:

log4j2.appender.console.type = Console
log4j2.appender.console.name = console
log4j2.appender.console.layout.type = PatternLayout
log4j2.appender.console.layout.pattern = %c/%C ${sd:type}/${map:key1} [%p] %m%n
log4j2.rootLogger.level = info
log4j2.rootLogger.appenderRef.file.ref = console

(вы должны использовать escape-последовательности, которые вы использовали, если вы настраиваете через etc/org.ops4j.pax.logging.cfg в Karaf).

person Grzegorz Grzybek    schedule 15.11.2019