Some of posts from this blog has been moved to dywicki.pl. You will be automatically redirected to new blog if you would submit comment.
New posts are published on dywicki.pl, this blog contains old content and it is not continued.

Niektóre posty z tego bloga zostały przeniesione do dywicki.pl. Zostaniesz automatycznie przekierowany jeśli bedzięsz chciał dodać komentarz.
Nowe posty sa publikowane na dywicki.pl, ten blog zawiera stare treści i nie jest kontynuowany.

Log4j, przejrzyste komunikaty

Filed under Framework,Java,log4j by

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ć.

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ć.

8 responses so far

8 Responses to “Log4j, przejrzyste komunikaty”

  1. Krótko, zwięźle i na temat! Wszystko w jednym miejscu.

  2. ajsmen says:

    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.

  3. Maciej Boniewicz says:

    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?

  4. 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

  5. Maciej Boniewicz says:

    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” :)

  6. 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

  7. Maciej Boniewicz says:

    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 :)

  8. 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.

Leave a Reply