Java exception log more

Logging exceptions in Java

By Andre Newman 13 Oct 2015

Logging is an essential component of any application, especially when a critical error occurs. Whether or not you recover from an exception, logging the problem can help you identify the cause of – and ultimately the solution to – potential problems in your application.

In this post, we’ll look at common approaches to Java exception handling and logging. The examples use Log4j2 , but the concepts apply to almost all modern logging frameworks.

When to Log Java Exceptions

One of the first questions that often comes up when logging exceptions is: Where should I put the logging code? Logging can take place in the method where the exception occurred, or it can follow the exception up the call stack until it’s eventually handled by one of the calling methods. Choosing one option over the other depends mostly on how your application is structured. In either case, the logger will need enough information to record the cause of the error.

Log at the Source

Logging close to the source of the error provides as much detail about the error as possible. For example, imagine we have a program that writes a string to a file. In our program, we have a class that opens a file, writes to it, and then closes it. In this class, we catch and log any IOExceptions:

While this approach lets us create specific log messages, it limits the available context. We have access to the stack trace, but we don’t know what particular course of action triggered the exception. Logging close to the source also adds complexity to the application, since it requires each component to provide its own logging implementation. This can be mitigated with frameworks such as SLF4J, but it still ends up adding redundancy and overhead.

Log Further up the Stack

Rather than log directly at the source, we can pass the exception up the stack and log it at a point where we have more contextual information. This can take place in the middle of the call stack, or even by an umbrella handler at the top. This can even be done using Thread.setDefaultUncaughtExceptionHandler() , which lets you specify an exception handler for uncaught exceptions for the entire application. Building off of the previous example, we can set the MyFileWriter class to throw an IOException, which we’ll catch in WriterClass.

With this approach, logging becomes more centralized and fewer components need to implement their own logging. The downside is that some of the granular information provided by the bottom-level component is lost. Fortunately, we still have access to the stack trace, which doesn’t change no matter how many times the exception is rethrown.

Linking Separate Log Events

Regardless of which approach you take, having the ability to associate multiple log events can greatly improve your ability to track down the cause of an exception. Imagine our WriterClass component is part of a large multi-user service. When it fails, we need to know which user triggered the exception and what they were doing when the exception was triggered. We can associate each event with a unique identifier – such as a user ID – that persists throughout the lifetime of the component.

Log4j2 introduced the concept of the Thread Context, which is built off of the Mapped and Nested Diagnostic Contexts used by Logback and other frameworks. As the name implies, the Thread Context is a thread-wide repository of related data. This data can be accessed by the logger to associate unique information with a log event, such as a user ID or session ID. This way, you can relate log events even if they originate from different sources or at different times.

Using the Thread Context Map, we can associate values with keys using the static ThreadContext.put() method:

Using the %X conversion pattern (or by using a structured layout), you can add values from the Thread Context into your logs. Using a log management service such as Loggly or even a command line tool such as grep, you can then search and sort entries for this particular user by matching the user ID.

What to Avoid When Logging Exceptions

The following tips are geared towards exception handling in general, but they can also prevent problems when logging.

Don’t Log and Throw

No matter which approach you take when handling exceptions, log the exception at the same time you handle the exception. If you log the exception and then throw it, there’s a chance that the exception will be logged again further up the call stack, resulting in two log events for the same error.

To prevent confusion, log once and log consistently.

Don’t Catch and Drop

A surprisingly common approach to exception handling is to catch the exception, then ignore it. Not only is the issue not handled, but we have no record of a problem ever occurring.

As a bare minimum, add a logging statement or display an alert to notify the user that an error occurred. Ideally you should log the stack trace provided by the exception, or throw the exception and log the event further up the stack.

Don’t Log Too Little

Another common (and misleading) practice is to log only a portion of the exception. While this does provide some details about the error, it usually results in the loss of more useful information. For example, this statement creates a log entry with a generic message followed by a very brief description of the exception:

With Log4j2 and other logging frameworks, you can pass the exception as a parameter to the logging method. By default, Log4j2 logs the exception’s stack trace along with the message provided. By extending Log4j2’s PatternLayout, or by switching to a more structured layout, you can include more detailed information about the stack trace.

Читайте также:  Ubuntu error writing permission denied

The key is to provide enough information for a developer to discover what went wrong, where it went wrong, and why it went wrong.

Don’t Catch General Java Exceptions

Catching the Exception class is like using a trawling net to catch a single fish. Not only does it make it more difficult to handle the exception in a specific way, but your program could end up catching exceptions it was never designed to handle.

Generally speaking, you should only catch exceptions that you can handle or delegate to the appropriate handler. Instead of using a catch-all, catch only the specific exception types that your code is likely to throw. You can do this by implementing separate catch blocks, each with their own exception-handling logic:

Starting with Java 7, you can catch multiple exception types in a single block by separating the exception type with a vertical bar ( | ).

While it’s still recommended to catch unique exceptions per catch block, this lets you simplify your code.

You should also consider using the Thread.setDefaultUncaughtExceptionHandler() method. As mentioned earlier in Log Further Up the Stack , setDefaultUncaughtExceptionHandler() can be used to log the event or perform a final action even if the error is unrecoverable.

Other Tips and Techniques

This post only covers a small subset of logging and exception-handling methods for Java. If you have any recommendations, feel free to leave them in the comments below.

Andre Newman is a software developer and writer on all things tech. With over eight years of experience in Java, .NET, C++, and Python, Andre has developed software for remote systems management, online retail, and real-time web applications. He currently manages 8-bit Buddhism , a blog that blends technology with spirituality.


Logging Exceptions: Where to Log Exceptions?

Jakob Jenkov
Last update: 2014-06-23

It is often a requirement that exceptions occurring in business applications must be logged, so they can be further examined by a human if necessary. Especially in web or server applications where the console output may not be available for examination. The exception log can be helpful at determining what went wrong, by either containing enough information to reveal the cause of the error, or aid in reproducing the exception.

When designing the logging of an application the question often arise: Where in the code should the exceptions be logged? Basically you have three different options:

    Bottom Level Logging
    Logging in the component where the exception occurs

Mid Level Logging
Logging somewhere in the middle of the call stack, where sufficient information is available (the context of the component call)

Top Level Logging
Logging centrally at the top of the call stack

The listing below shows a call stack where component A calls B. B calls other components, which in turn call the component F. Component A is the top level component, B etc. are a mid level components, and F is a bottom level component.

Bottom Level Logging

The first option you have is to log the exception in the component where it occurs. If you cannot alter the source of that component, then you will log as close as possible to the component method call throwing the exception. At first glance it may seem like a good design choice to encapsulate logging inside the component that throws the exception. However, this approach has a few drawbacks.

First of all logging has to be coded into every component capable of throwing an exception or calling a third party component that throws exceptions. This is a lot of logging code to write and maintain.

Second, if the component is to be reused across different applications, the component has no way of knowing how exceptions is to be logged in each application. You will have to let the logging strategy be pluggable in the component, and then the logging isn’t really encapsulated anyways.

Third the component that throws the exception may not really have sufficient information available to write a detailed and sensible log message. Say you have a component that writes an object to database. An exception is thrown because one of the fields is null. Can the component tell exactly what field was null in the log? Can it tell why this field was null? Perhaps the object was loaded with that field as null, or some action taken by the user caused it to become null. Or perhaps a bug in some code caused the field to become null. Does the component know what user was logged in when the exception ocurred? All this information might be needed for logging. The bottom level component may not have all that information available. The rest of the needed information may be available further up the call stack. This information cannot be logged if the logging is done inside the component, at bottom level.

Mid Level Logging

As alternative to logging at the bottom level, you can log at the mid level wherever enough information is available to write a satisfactory log message. This keeps the bottom level components free of logging code, but it has some drawbacks too.

At mid level you may not have all details available from the bottom level component that threw the exception. The bottom level component must then supply a detailed error text and perhaps error code, to make sensible logging possible at the mid level.

Читайте также:  Microsoft setup bootstrapper error

When logging at the mid level there is still a lot of logging code to write. At every place you catch and log an exception, you will have to insert almost the same logging code. If you later need to change the logging strategy it will take a lot of work. A shortcut would be to inject the logging code using aspect oriented programming, but I won’t get into that here.

Top Level Logging

Logging at the top level means that you have a single, central place in the code that catches all thrown exceptions and logs them. In a Java web application that could be a control servlet or perhaps a servlet filter. In a desktop application perhaps you your event handlers would extend a base event handler capable of catching and logging all exceptions thrown.

The advantage of top level logging is that you only have a single spot in the application where logging code is written and maintained. In addition to being easier to implement, this also makes it easier to postpone the logging implementation until later in the development process if needed. The logging code will only have to be implemented in one place, and most likely won’t change the total application call structure.

The disadvantage of top level logging is of course that this single central place doesn’t know anything about what went wrong in the bottom level component that threw the exception, or what the mid level code calling that component was trying to do. That makes writing sensible log messages somewhat harder.

Exception Enrichment

To overcome the lack of details available at the top level (and also to some degree at the mid level), you can enrich the exceptions as they propagate up the call stack towards the top level. Enriching exceptions is done by catching them, adding extra information and rethrowing them again. Rethrowing a caught Java exception will not change the embedded stack trace. The stack trace remains the same as when the exception was thrown first, by the bottom level component.

You will have to code your own exception class in order to make exception enrichment possible. Either that, or you’ll have to wrap the caught exception in a new exception and throw the new exception.

Summary and Recommendation

We have looked at three different logging strategies: Bottom, mid and top level logging.

I recommend using top level logging wherever possible, since it is easiest to code and maintain, and also to add later in the development process if you do not want to be bothered with it in the beginning. You may run into situations where an exception must be caught and dealt with at a lower level, but these situations don’t happen often in my experience. Most often, when an exception occurs that request or event handling is just skipped, and the exception logged along with sufficient information to determine the cause of the error, or reproduce it at least.


Логирование в Java / quick start

В ходе моей работы в компании DataArt я, в числе прочего, занимаюсь менторской деятельностью. В частности это включает в себя проверку учебных заданий сделанных практикантами. В последнее время в заданиях наметилась тенденция «странного» использования логеров. Мы с коллегами решили включить в текст задания ссылку на статью с описанием java logging best practices, но оказалось, что такой статьи в которой бы просто и без лишних деталей на практике объяснялось бы как надо писать в лог на Java, вот так вот с ходу не находится.

Данная статья не содержит каких-то откровений, в ней не рассматриваются тонкости какого либо из многочисленных java logging frameworks. Здесь рассказываю как записать в лог так, чтобы это не вызвало удивления у Ваших коллег, основная цель написания включить ее в список обязательного чтения для практикантов. Если все еще интересно, читайте дальше

Несколько разъяснений.

  • Весь код примеров использует java.util.logging framework. Вопрос «Какой из фреймворков логирования ниболее кошерен» я оставлю за кадром. Скажу только что до java.util.logging проще всего дотянуться ибо он уже идет вместе с JRE и на самом деле рассказанное в данной статье с минимальными косметическими правками верно для подавляющего большинства систем логирования.
  • В целом рецепты приведенные в данной статье не являются единственно верными, есть моменты о которых можно поспорить, но в целом эти рецепты используются многие годы, многими разработчиками, во многих проектах и они достаточно хороши чтобы им следовать если у Вас нет каких-то совсем уже серьезных возражений.
  • В статье не рассматриваются такие «продвинутые» топики как:
    • Конфигурирование уровней для отдельных логеров
    • Форматирования логов
    • Асинхронное логирование
    • Создание собственных уровней логирования в Log4J
    • Контекстное логирование
    • И многое другое
  • Слово logging я пишу по русски как логирование с одной буквой «г» в основном потом, что такой вариант перевода чаще встречается
  • Советы, что, с каким уровнем логировать я пожалуй тоже оставлю за кадром т.к. тут все сильно зависит от приложения, условий эксплуатации, отношений с заказчиком и т.п. тонких вещей.
Пример №1
  1. Логер это статическое поле класса инициализируемое при загрузке класса, имеет простое, короткое имя, важно чтобы во всех Ваших классах переменная логера называлась одинаково (это диктуется общим правилом, одинаковые вещи в программе должны делаться одинаковым образом).
  2. В качестве имени логера я использую имя класса, на самом деле это не единственный способ, можно пытаться организовать какую-то свою иерархию логирования (например transport layer/app layer для подсистем имеющих дело с обменом данными), но как показывает практика выдумывать и главное потом неукоснительно следовать такой иерархии крайне сложно, а вариант с именами логеров совпадающими с именами классов весьма хорош и используется в 99% проектов
  3. Здесь для записи в лог я использую короткий метод .info, а не более общий метод .log, так много лаконичнее
  4. Имя логера берется как SomeClass.class.getName(), а не как «», оба способа по идее одинаковы, но первый защищает Вас от сюрпризов при рефакторинге имени/пакета класса
Читайте также:  Microsoft msi error 1603

По сути тоже самое но букв больше и читается не так легко.

Замечание между примерами

Вы наверное обратили внимание, что все сообщения в примерах на английском языке. Это не случайно. Дело в том, что даже если все-все кто работает и будет работать с Вашим кодом говорят по русски, есть вероятность, что Вам придется просматривать лог сообщения на удаленном компьютере например через ssh при этом в большом количестве случаев Вы увидите примерно такое сообщение «. . . » (я безусловно знаю что через ssh можно протащить русские буквы, но вот почему-то далеко не всегда все оказывается настроенным должным образом).
Или даже на локальной машине в cmd вы можете увидеть что вот такое:
INFO: ╨Ъ╨░╨║╨╛╨╡-╤В╨╛ ╤Б╨╛╨╛╨▒╤Й╨╡╨╜╨╕╨╡ ╨▓ ╨╗╨╛╨│

С этим безусловно тоже можно бороться. Но не всегда легко объяснить заказчику на том конце телефонной трубки, как сделать так чтобы вместо крякозябр были видны русские буквы.
Совет: Пишите лог сообщения на английском языке, ну или в крайнем случае латинскими буквами.

Пример №2
  1. Если Вам необходимо залогировать исключение, для этого служит метод .log(level,message,exception)
  2. Если вы специально не настроили конфигурацию лог системы, сообщения с уровнем ниже info, например fine выводиться не будут. Но писать их по крайней мере для важных частей системы стоит. Когда что-то пойдет не так, Вы настроите более подробный уровень логирования и увидите много интересного.
  3. Слишком много лог сообщений, даже если они физически не пишутся в лог файл из-за своего слишком маленького уровня, могут существенно замедлить выполнение программы. Особенно если для подготовки самого сообщения надо потратить много ресурсов. Для этого есть метод .isLoggable(level) — он позволяет узнать пропустит ли текущая конфигурация логера данное сообщение

Если логировать только ex.toString(), то потом Вы не сможете понять в какой строке изначально сработало исключение.

Пример №3

Логер надо конфигурировать. Есть конфигурация по умолчанию она выводит в консоль все сообщения с уровнем INFO и выше. Она достаточно хороша, для разработки из IDE, но для реального приложения ее обычно неплохо бы подправить.

Какие тут есть варианты

По умолчанию: Файл для уровня INFO, вывод в консоль

#Console handler
handlers= java.util.logging.ConsoleHandler

Делаем логирование более подробным выводим еще и сообщения уровня FINE

#Console handler
handlers= java.util.logging.ConsoleHandler
java.util.logging.ConsoleHandler.level = FINE

Что мы тут сделали

  • Установили уровень FINE для корневого логера, просто чтобы сообщения пролезали внутрь лог системы.
  • И сказали что все что пролезет через лог систему надо выводить на консоль от уровня FINE и выше.
Выводим лог сообщения куда-то еще

Чем плох вывод на консоль? Консоль это по сути дела старый добрый stderr. Что это значит:

  • Если приложение запускается с помощью javaw Вы вообще ничего не увидите.
  • Если вывод идет в консоль и нужное вам сообщение промелькнуло 4 часа назад буфер консоли его уже съел, информация пропала.
  • Если вывод консоли направлен в файл java com.yourcompanyname.EntryClass 2>>application_log.txt и приложение работает не останавливаясь несколько недель — файл будет весьма и весьма большим, рискуя занять весь диск.

Чтобы решить эти проблемы был придуман java.util.logging.FileHandler — хэндлер который выводит лог сообщения в файл. При этом он умеет ротировать файлы, т.е. после достижения максимально допустимого размера, он дописывает в файл текщуее лог сообщение и открывает новый файл с инкрементальным префиксом. И так по кругу. Например

создаст вот такие файлы (последняя колонка — размер в байтах)

Мы указали максимальный размер 50 байтов, в реальной жизни надо скорее указывать не меньше мегабайта, например вот так (я знаю, что 1000000 это чуть меньше мегабайта, но кому охота по памяти писать 1048576, если суть дела это фактически не меняет)

В примере, как мы видим, файлы получились больше 50 байт потому что размер по сути округляется вверх до последнего целого лог сообщения. Т.е. если Вы укажете размер 1 байт и запишете лог сообщение размером в 1000 байт то размер файла станет 1000 байт и после этого лог сообщения файл закроется и откроется следующий.

copy & paste конфиг для реальной жизни, его вполне хватает для большинства service, console и desktop приложений.

Последняя часть магии

Ну и последнее о чем осталось рассказать — как собственно сконфигурировать логер из файла свойств. Есть два способа:

  1. Из командной строки запуска приложения
  2. В первых строчках кода Вашего приложения

Первый чуть более правильный ибо он декларативный и работает сразу, до того как начал работать код Вашего приложения.

Вот так

java com.dataart.application.ClassName

Но к сожалению менять строку запуска не всегда можно или не всегда удобно. Второй способ тоже неплохо работает.

  • Здесь MainApplicationEntryClass — это класс — точка входа в Ваше приложение, видимо имя класса у Вас будет другое
  • Сам файл как правило в таких случаях кладется в корень иерархии классов и выглядит это например вот так

Что осталось за кадром

В реальной жизни как минимум половина всех Java приложений это web приложения. Сама техничка логирования в них совершенно не отличается от изложенного выше. Ну может быть за тем исключением что разные сервера приложений могут использовать разные библиотеки логирования такие например как:

  • Log4J
  • JULI logger (строго говоря это не вполне самостоятельный фреймворк, а своего рода надстройка над java.util.logging)
  • SLF4J
  • Commons Logging

Соответственно несколько отличается настройка и имена методов. Но сам принцип меняется мало. Конкретные особенности как правило хорошо описаны в документации на сам сервер приложений, например

  • Tomcat
  • JBoss
  • Resin


Оцените статью