12 января 2016 г.

log4j (v.1) пример настройки трассировки (TRACE) нужного модуля

Настройка логирования для log4j версии 1
Пусть есть приложение, которое использует библиотеку log4j-1.2.17.jar

Параметры для log4j удобно передавать через внешний файл. Внешний файл удобно редактировать.

Запуск приложения с указанием конфига логов

Можно создать командный файл start.SampleConsoleServer.bat с текстом:
java -jar ^
    -Dlog4j.configuration=file:log4j.properties ^
    Server.jar ^
    com.blogger.server.SampleConsoleServer

Предполагается, что в одном каталоге находится три файла:
  • Server.jar - java-приложение, реализуещее класс com.blogger.server.SampleConsoleServer;
  • log4j.properties - файл настроек логирования для log4j версии 1;
  • start.SampleConsoleServer.bat - командный файл для запуска Server.jar.
Если бы файл log4j.properties находится не в текущем каталоге, а в каталоге на уровень выше, то надо бы было написать:
java -jar ^
    -Dlog4j.configuration=file:../log4j.properties ^
    Server.jar ^
    com.blogger.server.SampleConsoleServer

Пример содержимого файла log4j.properties

# Default logging level, log on console only (add ',file' to log on file as well)
#log4j.rootLogger=TRACE, stdout, fileTrace

log4j.logger.com.blogger.server.SampleConsoleServer=TRACE, stdout, fileTraceServer
log4j.logger.com.blogger.client=TRACE, stdout, fileTraceClient 

#Общий вывод в консоль
log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.Target=System.out
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
#log4j.appender.stdout.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss} %p %c{1}:%L - %m%n#log4j.appender.stdout.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss}\t%p\t%c{1}:%L\t-\t%C\t-\t%l\t-\t%M\t-\t%m%n
log4j.appender.stdout.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss}\t%p\t-\t%l\t-\t%m%n

#Лог сервера
log4j.appender.fileTraceServer=org.apache.log4j.RollingFileAppender
log4j.appender.fileTraceServer.maxFileSize=100MB
log4j.appender.fileTraceServer.maxBackupIndex=50
log4j.appender.fileTraceServer.file=trace.file.server.log
log4j.appender.fileTraceServer.layout=org.apache.log4j.PatternLayout
#log4j.appender.fileTraceServer.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss}\t%p\t%c{1}:%L\t-\t%C\t-\t%l\t-\t%M\t-\t%m%n
log4j.appender.fileTraceServer.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss}\t%p\t-\t%l\t-\t%m%n 

#Лог клиента
log4j.appender.fileTraceClient=org.apache.log4j.RollingFileAppender
log4j.appender.fileTraceClient.maxFileSize=100MB
log4j.appender.fileTraceClient.maxBackupIndex=50 
log4j.appender.fileTraceClient.file=trace.file.client.log 
log4j.appender.fileTraceClient.layout=org.apache.log4j.PatternLayout 
#log4j.appender.fileTraceClient.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss}\t%p\t%c{1}:%L\t-\t%C\t-\t%l\t-\t%M\t-\t%m%n 
log4j.appender.fileTraceClient.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss}\t%p\t-\t%l\t-\t%m%n

Описание конфигурационного файла log4j.properties


1. Указываются настройки для логгеров с разными именами

# Default logging level, log on console only (add ',file' to log on file as well)
#log4j.rootLogger=TRACE, stdout, fileTrace

log4j.logger.com.blogger.server.SampleConsoleServer=TRACE, stdout, fileTraceServer
log4j.logger.com.blogger.client=TRACE, stdout, fileTraceClient

Настройки логирования для всех логгеров

Можно настроить логирование которое будет применяться логгерам log4j с любым именем. Ключевым словом тут является rootLogger. Далее указываются Уровень логирования и куда записывать логи. В примере выше такая настройка закомментивана.
# Default logging level, log on console only (add ',file' to log on file as well)
log4j.rootLogger=TRACE, stdout, fileTrace

Но если бы она не была закомментирована, то сообщения с уровнем TRACE и выше для любого логгера записывались бы в лог согласно настройкам
log4j.appender.stdout
и
log4j.appender.fileTrace

Настройки логирования для конкретного класса и его подклассов

Обычно, логгеры создаются с именем, соответствующим имени класса. Пример java-кода ниже.
package com.blogger.server;

import org.apache.log4j.Logger;

public class SampleConsoleServer {
    protected static final Logger LOG = Logger.getLogger(SampleConsoleServer.class);

    public void processRequest(String request) {
        if (LOG.isTraceEnabled()) LOG.trace("processRequest(String request)");
        //...
        if (request == null) {
            LOG.fatal("Request is null");
            throw new NullPointerException();
        }
        //...
    }
}

Если логгер создавался по описанию класса, то имя логгера соотвествует полному имени класса: com.blogger.server.SampleConsoleServer.
В файле log4j.properties настройки для такого именованного логгера задаются после указания имени логгера:

log4j.logger.{Имя логгера}={Уровень}, {Обработчик 1}, {Обработчик 2}, ...
В имени логгера могут быть точки. Наличие точек в имени логгера и создаёт особую магию, позволяя задать настройки для конкретного класса или для логгеров всех классов из пакета, но об этом позже.

Пример настроек логирования для конкретного класса в примере выше это строка:
log4j.logger.com.blogger.server.SampleConsoleServer=TRACE, stdout, fileTraceServer

Тут говорится для логгера с именем com.blogger.server.SampleConsoleServer нужно все сообщения с уровнем TRACE и выше записывать в лог согласно настройкам с именами stdout и fileTraceServer.

Если бы в классе  SampleConsoleServer был подкласс ServerSettings с логгером имя которого com.blogger.server.SampleConsoleServer.ServerSetting, то также бы использовались настройки логирования:
log4j.logger.com.blogger.server.SampleConsoleServer=TRACE, stdout, fileTraceServer

Так как они соответствуют имени логгера.

Настройки логирования для всех классов из указанного пакета

Также в примере есть настройка для логгера com.blogger.client.
log4j.logger.com.blogger.client=TRACE, stdout, fileTraceClient 

Тут предполагается, что com.blogger.client - пакет, а не название класса. Что в этом пакете есть классы:
  • com.blogger.client.Client1,
  • com.blogger.client.Client1.Settings,
  • com.blogger.client.DefaultClient,
  • com.blogger.client.AbstractClient.
Что для этих классов созданы логгеры с соотвествующими именами. И все эти логгеры будут использовать настройки логирования com.blogger.client.

2. Задаются настройки обработчиков логов

#Общий вывод в консоль
log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.Target=System.out
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
#log4j.appender.stdout.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss} %p %c{1}:%L - %m%n#log4j.appender.stdout.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss}\t%p\t%c{1}:%L\t-\t%C\t-\t%l\t-\t%M\t-\t%m%n
log4j.appender.stdout.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss}\t%p\t-\t%l\t-\t%m%n

#Лог сервера
log4j.appender.fileTraceServer=org.apache.log4j.RollingFileAppender
log4j.appender.fileTraceServer.maxFileSize=100MB
log4j.appender.fileTraceServer.maxBackupIndex=50
log4j.appender.fileTraceServer.file=trace.file.server.log
log4j.appender.fileTraceServer.layout=org.apache.log4j.PatternLayout
#log4j.appender.fileTraceServer.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss}\t%p\t%c{1}:%L\t-\t%C\t-\t%l\t-\t%M\t-\t%m%n
log4j.appender.fileTraceServer.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss}\t%p\t-\t%l\t-\t%m%n 

#Лог клиента
log4j.appender.fileTraceClient=org.apache.log4j.RollingFileAppender
log4j.appender.fileTraceClient.maxFileSize=100MB
log4j.appender.fileTraceClient.maxBackupIndex=50 
log4j.appender.fileTraceClient.file=trace.file.client.log 
log4j.appender.fileTraceClient.layout=org.apache.log4j.PatternLayout 
#log4j.appender.fileTraceClient.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss}\t%p\t%c{1}:%L\t-\t%C\t-\t%l\t-\t%M\t-\t%m%n 
log4j.appender.fileTraceClient.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss}\t%p\t-\t%l\t-\t%m%n

Имена обработчиков логов

У обработчиков логов есть имена. В примере выше это:
  • stdout;
  • fileTraceServer;
  • fileTraceClient.

Тип  обработчика логов

Для лога указывается тип. Самые ходовые типы в моей практике:
  • org.apache.log4j.ConsoleAppender - вывод на консоль;
  • org.apache.log4j.RollingFileAppender - вывод в файл.

Формат лога

Для большинства ситуаций отладочного лога достаточно короткого формата:
%d{yyyy-MM-dd HH:mm:ss}\t%p\t-\t%l\t-\t%m%n

В лог запишутся:
  • %d дата в формате yyyy-MM-dd HH:mm:ss;
  • %p уровень события;
  • %l строка кода с указанием класса, метода, имени исходного файла и номера строки;
  • %m добавляемое в лог сообщение;
  • %n перевод строки;
  • \t символы табуляции;
  • - разделители.
Пример строк лога, соотвествующих указанному формату:
2015-12-14 18:53:15 TRACE - com.blogger.client.Handler.read(Handler.java:330) - 
2015-12-14 18:53:15 TRACE - com.blogger.client.Handler.read(Handler.java:346) - Read token duration: 185048 ms
2015-12-14 18:53:15 ERROR - com.blogger.client.Handler.read(Handler.java:360) - ProxyServer closed channel
2015-12-14 18:53:15 FATAL - com.blogger.client.Client2.run(Client2.java:164) - ProxyServer closed read channelData
com.blogger.exception.ReadControlChannelException: ProxyServer closed read channelData
 at com.blogger.client.Handler.read(Handler.java:361)
 at com.blogger.client.Handler.process(Handler.java:219)
 at com.blogger.client.Client2.run(Client2.java:151)
 at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
 at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
 at java.lang.Thread.run(Thread.java:745)
2015-12-14 18:53:15 TRACE - com.blogger.client.Client2.run(Client2.java:170) - Close all
2015-12-14 18:53:15 TRACE - com.blogger.client.Client2.tryClose(Client2.java:183) - Close channel java.nio.channels.SocketChannel[connected local=/192.168.150.58:55851 remote=/77.88.99.00:1234]

или без подсветки смысловых частей:
2015-12-14 18:53:15 TRACE - com.blogger.client.Handler.read(Handler.java:330) - 
2015-12-14 18:53:15 TRACE - com.blogger.client.Handler.read(Handler.java:346) - Read token duration: 185048 ms
2015-12-14 18:53:15 ERROR - com.blogger.client.Handler.read(Handler.java:360) - ProxyServer closed channel
2015-12-14 18:53:15 FATAL - com.blogger.client.Client2.run(Client2.java:164) - ProxyServer closed read channelData
com.blogger.exception.ReadControlChannelException: ProxyServer closed read channelData
 at com.blogger.client.Handler.read(Handler.java:361)
 at com.blogger.client.Handler.process(Handler.java:219)
 at com.blogger.client.Client2.run(Client2.java:151)
 at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
 at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
 at java.lang.Thread.run(Thread.java:745)
2015-12-14 18:53:15 TRACE - com.blogger.client.Client2.run(Client2.java:170) - Close all
2015-12-14 18:53:15 TRACE - com.blogger.client.Client2.tryClose(Client2.java:183) - Close channel java.nio.channels.SocketChannel[connected local=/192.168.150.58:55851 remote=/77.88.99.00:1234]

По такому логу можно увидеть трассировку выполнения всех методов. Ошибки. Номера строк, в которых произошли логируемые события. Удобно, понятно.

Комментариев нет:

Отправить комментарий