среда, 30 октября 2013 г.

Java EE: Удобные логи - это просто

- Привет, тут у меня клиент, он не видит в архиве своих операций. Глянь плиз, что у него не так? Только быстрее, он VIP, он злой и висит на линии...

Если вы пишите серверные приложения, то такие просьбы девочек из саппорта вам знакомы. И знакомо то чувство отвращения, злости и отчаяния с которым вы бросаете свой незаконченный рефакторинг в самом неподходящем месте, чтобы залезть в консоль и смотреть логи.
А логи, как на зло пишутся по старинке, потому что разбираться с log4j некогда, да и неохота... Вот если бы сливать логи в базу, да запилить админку... Но когда этим заниматься? 100500 задач в разработке а тут ещё эти логи.
Как же быть? Выделить день-другой и переписать логирование на какой-нибудь фреймворк? Это можно. Но мы ведь программисты, давайте сначала оценим задачу. Итак чего бы нам хотелось?
  • Логи не должны писаться вперемешку. Все записи в контексте одного запроса должны в логах находиться в одном месте, "пакетом".
  • Все записи одного уровня должны маркироваться общим тегом
  • Вместе с пакетом записей должна быть возможность вывести в лог произвольные данные (например id клиента и т.п.), относящиеся к этому запросу. 
И всё? И для этих трёх простых вещей тащить в свой проект ещё один фреймврок? Нет уж, давайте напишим несколько строк кода и покончим с этим ;)
Пишем наш логгер:

public class Logger {
 
 private static ConcurrentHashMap<Long, StringBuilder> data = new ConcurrentHashMap<Long, StringBuilder>();
    private static final String TAG = "MYSERVICE: ";
    private static final int MAX_TRACE_ELEMENTS = 5;
    public static enum Level {VARNING, ERROR}
 
    public static void log(Object o, Level l) {
        Long id = Thread.currentThread().getId();
        StringBuilder sb = data.get(id);
        if (sb==null) sb = new StringBuilder();
        if (o instanceof Exception) {
            Exception e = (Exception) o;
            sb.append(TAG).append(" ").append(l.name()).append(": ").append(e.getMessage()).append("\n");
            for (int i=0; i<MAX_TRACE_ELEMENTS; i++) {
                try {
                    sb.append(TAG).append(" ").append(l.name()).append(": ").append(e.getStackTrace()[i].toString()).append("\n");
                } catch (IndexOutOfBoundsException ioobe) {}
            }
        } else {
            sb.append(TAG).append(" ").append(l.name()).append(": ").append(o.toString()).append("\n");
        }
        data.put(id, sb);
    }
 
    public static void flush() {
        flush(null);
    }
 
    public static void flush(Map<String, String> params) {
        Long id = Thread.currentThread().getId();
        StringBuilder sb = data.get(id);
        if (sb!=null) {
            System.err.println("===================================>>>>>");
            if (params!=null) {
                System.err.print("--------------");
                for (String key : params.keySet()) {
                    System.err.print("&"+key+"="+params.get(key));
                }
                System.err.println("--------------");
            }
            System.err.println(sb.toString());
            data.remove(id);
            System.err.println("<<<<<====================================");
        }
    }
}

~50 строк кода. Работает это всё очень просто. При первом вызове метода log() автоматически создаётся строковый буфер и укладывается в Map, с id текущего потока в качестве ключа. Все последующие вызовы просто добавляют строки в этот буфер. Чтобы записать содержимое буфера и удалить его из памяти в конце обработки запроса нужно вызвать метод flush(). В этот же метод можно передать и дополнительные переменные, если нужно.

Используем наш Logger:

Везде, где нужно что-то вывести в лог используем метод Logger.log(). Ничего инициализировать или "инжектить" не нужно. В этот метод можно передать как строку, так и Exception. В последнем случае будет выведено 5 верхних строк его StackTrace. Вторым параметром передаём экземпляр Logger.Level, определяющий уровень ошибки.

В принципе это всё. Решение, конечно, не претендует на громкое звание универсального всеобъемлющего фреймворка. Но давайте относиться к проблеме адекватно. Эти 50 строк кода позволят легко разбираться с любым проблемным запросом к нашему серверу. В подавляющем большинстве случаев большего вам и не понадобится. А если и понадобится, то наш Logger также легко и расширить в ту сторону, какая будет нужна.

Продолжение темы смотрите тут.

3 комментария:

  1. ок. ljg4j наверное не феншуйно использовать, с этим не буду спорить.
    но прочитав данный пример кода у меня возникло несколько вопросов, которые я не мог не задать:

    1. Зачем собирать лог, а потом всегда делать flush, хотя всеравно пишешь в System.err. Это реально удобно?
    2. Я просто считал, что лог должен быть в реалтайме..
    да, можно его оптимизировать буффером, чтбы не паузить потоки, но всеравно писать сразу
    но фишка то в том, что в System.err тоже не паузит поток)
    3. И теперь интересный вопрос..
    а если перед вызовом flush крашнется приложение ?
    и не узнаешь ничего из этих логов.
    или здесь еще нужен хендлер исключений, чтобы флашить перед крашем ?))
    4. Ну а теперь вечный вопрос. А если сработает GC и захавает твои логи, потому что ссылок на них то нигде нету?
    5. ConcurrentHashMap может запаузить поток. И если взять уже момент синхронизации потоков, почему так строго сделано?

    Итог: если все правильно написать и рассмотреть все будущие моменты и импрувы для кофмортной разработки, то напишем свой log4j.. Так что можно его смело юзать.

    ОтветитьУдалить
    Ответы
    1. По порядку:
      1. и 2. Лог не может быть "в реалтайме" и сгруппированным в контексте запроса одновременно. В большинстве случаев задержка вывода в лог на 100-200 мс не так неприятна, как необходимость выискивать в общем хаосе всё что происходило именно с этим запросом.
      3. А вот это действительно неприятно. Чтобы избежать этого нужно ловить все "непойманные" исключения в общем предке всех сервлетов. И да, флушить лог принудительно. Обычная, кстати, практика, чтобы не плеваться StackTrace-ами на страницу клиенту.
      4. Если так рассуждать, то вообще нельзя использовать static переменные, а то "как бы дурной GC их не захавал". Скажу лишь, что такая схема логирования уже полгода используется на довольно большом проекте и никаких проблем с GC не обнаружилось. Не такой уж он и глупый, наш GC.
      5. ConcurrentHashMap, по-моему, достаточно толковый инструмент для этой задачи. Синхронизированный, неблокирующий, операции чтения вообще никогда не приводят к блокировкам. Чем не идеальный выбор? Впрочем, если есть другие предложения - милости просим в личку ;)

      Удалить
  2. Вы в курсе что у вас не синхронизована запись в System.err ?? т.е.е два потока вызвав метод записи приведут к тому что в syserr будет все вперемешку.
    И чем вас не устроил log4j, logback?

    ОтветитьУдалить