Oct 15 2008
Log4j, przejrzyste komunikaty
Filed under Framework,Java,log4j by Łukasz Dywicki
Log4j jest najpopularniejszą biblioteką do logowania dla Javy. Została ona wydana już jakiś czas temu i w chwili obecnej rozwija się znacznie wolniej niż kiedyś, warto jednak nadmienić że społeczność wciąż dostarcza nowych możliwości. Może najpierw o samej strukturze log4j.
Najważniejsze elementy
Log4j ma kilka składowych:
- Appender
- Layout
- Category
Dzisiaj skupię się tylko na dwóch pierwszych. Appender jest odpowiedzialny za zapis bądź wysyłanie komunikatów do wybranego miejsca podczas gdy Layout konwertuje wpis do określonego formatu.
Z najciekawszych Appenderów wymienię
- RollingFileAppender rotuje logi do określonego rozmiaru, po osiągnięciu np 10mb kopiuje stary plik zgodnie ze schematem i zaczyna zapisywać do nowego.
- DailyRollingFileAppender zachowuje się podobnie jak wyżej wymieniony z tym, że umożliwia zapis z podziałem na lata, miesiące, dni czy nawet minuty.
- SyslogAppender, który wysyła komunikaty do Sysloga
- LF5Appender wyświetlający logi w okienku tworzonym przy pomocy Swinga.
- SMTPAppender wysyłający maile z komunikatami. Jeśli się go źle skonfiguruje gwarantowane zapchanie skrzynki ;-)
- NagiosAppender przesyłający komunikaty do Nagiosa, narzędzia służącego do monitorowania.
Mając już appender, który wie gdzie zapisywać wypada powiedzieć Log4j też co powinien zapisywać.
- HTMLLayout produkujący tabelę HTML
- PatternLayout posiadający możliwość określenia “szablonu” wpisu.
Więcej Layoutów można znaleźć w Javadocu Log4j.
Jako, że zdecydowanie najczęściej używa się PatternLayout dodam parę słów na temat tego co potrafi. We wzorze który będzie później użyty do stworzenia komunikatu możemy używać następujących wyrażeń:
- %c kategoria zdarzenia
- %C nazwa klasy z której zostało wysłane zdarzenie
- %d data zdarzenia (przykład: %d{HH:mm:ss,SSS} )
- %m komunikat wysłany z aplikacji
- %n separator lini
- %p priorytet zdarzenia
- %r ilość milisekund, które zdążyły upłynąć od startu aplikacji
- %t nazwa wątku z którego zostało wysłane zdarzenie
- %x kontekst diagnostyczny powiązany z wątkiem (wie ktokolwiek co to znaczy?)
- %% pojedynczy znak %
- %M nazwa metody z której zostało wysłane zdarzenie (uwaga, bardzo wolne)
- %L numer linii z której zdarzenie pochodzi (uwaga, bardzo wolne)
- %F nazwa pliku z którego pochodzi zdarzenie (uwaga, bardzo wolne)
- %l informacja o wywołującym zdarzenie (uwaga, bardzo wolne, wskazuje na lokalizację z naszego kodu)
Przykłady modyfikatorów:
- %20c dodaje spacje z lewej strony jeśli nazwa kategorii jest krótsza niż 20 znaków
- %-20c dodaje spacje z prawej strony jeśli nazwa kategorii jest krótsza niż 20 znaków
- %.30c przycina kategorię pozostawiając ostatnie 30 znaków
- %20.30c wypełnia z lewej strony nazwę kategorię spacjami do 20 znaków oraz przycina początkowe znaki jeżeli jest dłuższa on 30 znaków
- %-20.30c analogicznie jak wyżej, z tym że znaki zostaną dodane z prawej strony. Ze swojej strony polecam używanie formatu np %-20.20, co zagwarantuje że element będzie miał zawsze 20 znaków. Jeśli pozostawimy -20.30 to element będzie miał 20 znaków jeśli kategoria jest zbyt krótka a 30 gdy będzie za długa
Przykład konfiguracji
Log4j można konfigurować na kilka sposobów. Programowo, przez plik properties oraz konfigurację XML. Zdecydowanie najpopularniejszy jest plik properties. Jego użycie jest banalnie proste. Włączamy log4j.jar do tak by był on dostępny w classpathu, a następnie tworzymy plik log4j.properties, który domyślnie jest poszukiwany przez bibliotekę jeśli nie została przekazana żadna konfiguracja. Aby jednak to się stało nasz kod musi spróbować wysłać jakąś wiadomość do Log4j.
log4j.rootLogger DEBUG, out
# loggery
log4j.logger.org.springframework INFO
log4j.logger.org.apache.activemq INFO
log4j.logger.org.apache.activemq.spring WARN
log4j.logger.org.apache.servicemix DEBUG, stdout
#appendery
log4j.appender.stdout org.apache.log4j.ConsoleAppender
log4j.appender.stdout.layout org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern %d{ABSOLUTE} | %-5p | %t | %c | %m%n
log4j.appender.out org.apache.log4j.DailyRollingFileAppender
log4j.appender.out.DatePattern ‘-‘yyyy-MM-dd’.log’"/>
log4j.appender.out.layout org.apache.log4j.PatternLayout
log4j.appender.out.layout.ConversionPattern %d{ABSOLUTE} | %-5p | %t | %c | %m%n
log4j.appender.out.file E:/fuse-esb/data/log/servicemix
Założenie powyższej konfiguracji jest następujące. Domyślny poziom logowania jest ustawiony na DEBUG a komunikaty są zapisywane do pliku (rootLogger). Zdefiniowane są dwa appendery stdout oraz out. Pierwszy jest użyty tylko dla paczki org.apache.servicemix. Pozostałe loggery mają określony tylko poziom logowania. Pliki z logami będą dzielone na dni, także w lokalizacji E:/fuse-esb/data/log/ po 3 dniach działania od 13 do 15 października będziemy mieli 3 pliki:
- servicemix – logi z bierzącego dnia
- servicemix-2008.10.14.log – logi z 14 października
- servicemix-2008.10.13.log – logi z 13 października
Mam nadzieję że od dzisiaj Log4j będzie Wam drodzy czytelnicy mówił więcej i prościej. Jeśli są jakieś kwestie które pozostają niewyjaśnione – proszę pytać.
Krótko, zwięźle i na temat! Wszystko w jednym miejscu.
Dla wszystkich którzy trafili tutaj szukając pomocy w poznawaniu log4j:
Add:
> %x kontekst diagnostyczny powiązany z wątkiem (wie ktokolwiek co to znaczy?)
jest publiczna klasa ze statycznymi metodami org.apache.log4j.NDC:
public class NDC {
// Used when printing the diagnostic
public static String get();
// Remove the top of the context from the NDC.
public static String pop();
// Add diagnostic context for the current thread.
public static void push(String message);
// Remove the diagnostic context for this thread.
public static void remove();
}
w każdym miejscu w kodzie możemy zrobić push(xxx) i w ten sposób dodać wartość do kontekstu diagnostycznego powiązanego z wątkiem. Jest to bardzo pomocne, jeżeli np: mamy klasy których funkcjonalność wykorzystywana jest w wielu miejscach. Teraz chcemy dokładnie wiedzieć kto wywołał metodę w której zalogowaliśmy niepożądany przebieg. Normalnie musielibyśmy przeanalizować log (który może być bardzo długi) i wywnioskować w którym momencie w przebiegu programu jesteśmy. Jeżeli natomiast przy wejściu do pewnych większych etapów dodamy push z odpowiednim opisem (przy wyjściu pop), to dana linia logu poza wiadomością i ewentualnymi informacjami o klasie która ją wyprodukowała, będzie zawierała stos ‘kontekstu diagnostycznego powiązanego z wątkiem’. Dzięki temu patrząc na coś na kształt stackTrace’u będziemy moglo dokładnie stwierdzić w którym miejscu w przebiegu programu został wyprodukowany oglądany log.
Bardzo fajny artykuł :) Ale mam pytanie, ustawiłem domyślny tryb logowania na FATAL (nie chcę nic logować), a tryb TRACE dla HQL’li. W tym momencie, przestało logować HQL’e. Co robię nie tak?
Cześć Maciej,
Jeśli idzie o logowanie z poziomem TRACE to być może masz ustawiony threshold na appenderze, który to blokuje. Jeśli wcześniej to działało, a teraz nie działa – sprawdź kategorię z której korzysta Hibernate.
Spróbuj np:
log4j.logger.org.hibernate.hql.ast.AST=debug
log4j.logger.org.hibernate.SQL=debug
log4j.logger.org.hibernate.hql=debug
Pozdrawiam,
Łukasz
Działa :) ale niestety działa nie do końca poprawnie :/
Obecnie pliczek mam taki:
log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.conversionPattern=%d{ABSOLUTE} | %-5p | %t | %c | %m%n
log4j.rootLogger = error,stdout
log4j.logger.org.hibernate.hql.ast.AST=debug
log4j.logger.org.hibernate.SQL=debug
log4j.logger.org.hibernate.hql=debug
Gdy zmienię log4j.rootLogger na debug,stdout – działa ale wywala masę śmieci,
natomiast bez tego nie loguje nic. Teoretycznie mógłbym to spróbować wygrepować (i pewnie tak zrobię jak nie zadział nic innego ;) ), natomiast jeśli się da, fajnie byłoby to zrobić “porządnie” :)
Maciej,
U mnie z log4j 1.2.15 całość działa z hibernate.show_sql ustawionym na false.
3:37:24,736 2618 [983603720@qtp-1433743869-5] TRACE org.hibernate.hql.classic.QueryTranslatorImpl – compiling query
23:37:24,740 2622 [983603720@qtp-1433743869-5] DEBUG org.hibernate.SQL –
select
vehiclebod0_.id as id36_,
vehiclebod0_.name as name36_
from
vehicle_body_types vehiclebod0_
Konfiguracja log4j:
# Set root category priority to INFO and its only appender to CONSOLE.
log4j.rootCategory=WARN, CONSOLE, LOGFILE
# CONSOLE is set to be a ConsoleAppender using a PatternLayout.
log4j.appender.CONSOLE=org.apache.log4j.ConsoleAppender
log4j.appender.CONSOLE.Threshold=WARN
log4j.appender.CONSOLE.layout=org.apache.log4j.PatternLayout
log4j.appender.CONSOLE.layout.ConversionPattern=%-4r [%t] %-5p %c %x – %m%n
# LOGFILE is set to be a File appender using a PatternLayout.
log4j.appender.LOGFILE=org.apache.log4j.DailyRollingFileAppender
log4j.appender.LOGFILE.File=shippingstock.log
log4j.appender.LOGFILE.Append=true
#log4j.appender.LOGFILE.Threshold=DEBUG
log4j.appender.LOGFILE.layout=org.apache.log4j.PatternLayout
log4j.appender.LOGFILE.layout.ConversionPattern=%d{ABSOLUTE} %-4r [%t] %-5p %c %x – %m%n
log4j.logger.org.code_house=DEBUG
CONSOLE.
log4j.logger.org.springframework=WARN
log4j.logger.org.springframework.jpa=WARN
#log4j.logger.org.springframework.web=DEBUG
#log4j.logger.org.hibernate=WARN,LOGFILE
log4j.logger.org.hibernate.engine.query=WARN
#log4j.logger.org.springframework.security=DEBUG
log4j.logger.org.hibernate.hql.ast.AST=TRACE
log4j.logger.org.hibernate.SQL=TRACE
log4j.logger.org.hibernate.hql=TRACE
Niestety to rozwiązanie także mi nie zadziałało (może mam dziwnego hibernata, albo tomcata, albo jeszcze coś innego) nawet jak zmieniłem logowanie do pliku (którego nie mógł mi utworzyć pomimo nadanych uprawnień) na logowanie do drugiej konsoli, to i tak bez ogólnego trybu debug nic nie pokazywał.
Za to udało mi się uzyskać takie rozwiązanie – loguje HQL’e, SQL’e oraz napis “compiling query” ;P. W sumie takie coś już można dość łatwo przegrepować :)
log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.conversionPattern=%d{ABSOLUTE} | %-5p | %t | %c | %m%n
log4j.rootLogger = error,stdout
log4j.logger.net.sf.hibernate.hql.QueryTranslator=debug
Przy okazji mam nadzieję że się to komuś przyda :)
Maciej,
Spróbuj czegoś takiego:
log4j.logger.net.sf.hibernate.hql.QueryTranslator=debug, myappender
log4j.additivity.net.sf.hibernate.hql.QueryTranslator=true
Powinno to wrzucić logi tylko do myappender. Additivity blokuje przesyłanie eventów do root loggera.