Java EE: Делаем логи ещё удобнее

Где-то месяц назад я описывал простую систему логирования для web-приложений, которая позволяла, кроме всего прочего, группировать данные в логах в контексте одного запроса. Фича весьма удобная и я с удовольствием использую её в своих проектах. Но, как водится, в процессе эксплуатации вылезли и недоработки. Этот прост о том, как развивалась система, и о том, как она теперь работает.

Что было не так со старой системой?
Да, она группировала вывод в контексте одного запроса к серверу. Вернее в контексте одного потока, запущенного servlet-контейнером для обработки этого запроса. Если servlet не порождал новых потоков, то всё было нормально, но вот если новые потоки создавались, мы тут получали проблему. Логгер писал их отдельно, а значит, вперемешку с остальными потоками. Мелочь, а неприятно.



Как это исправить?
Первое решение напрашивалось само: Вместо метода Logger.log(Object o) использовать метод Logger.log(Object o, long id), вторым параметром в который передавать id родительского потока. Вроде бы несложно, но это только на первый взгляд. Порождаем поток, отдаём в него id предка, во всех местах при выводе в лог используем этот id. Но из потока вызываются куча других методов других классов. Что делать? Передавать и туда наш id предка? Так этот параметр становится "белой ниткой", которая пронизывает весь проект, добавляя ему излишней связности. Как же быть? Давайте глубже присмотримся к нашим методам логирования:

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

Буфер для временного хранения логов потока хранится в Map с id потока в качестве ключа. Сам этот id получается вызовом метода getId() класса Thread. Чтобы получить от этого метода id предка достаточно переопределить этот метод. Делаем наследник Thread, который и будем теперь использовать везде в проекте:

public abstract class WorkerBased extends Thread {
 
    private long id;
 
    public WorkerBased(long id) {
        this.id = id;
        this.start();
    }
 
    public abstract void process();
 
    @Override
    public void run() {
        process();
        Logger.flush();
    }
 
    @Override
    public long getId() {
        return this.id;
    }
}

Вызываем новый поток из сервлета теперь так:
new Worker(Logger.getId());
... и это единственное место, где мы явно заботимся о передаче id предка. В самом потоке делаем всё как обычно:
Logger.log("some string");

Но есть ещё одна проблема...
Чтобы "сбросить" в лог буфер с данными конкретного потока нужно вызвать Logger.flush(). Это нужно сделать в конце обработки запроса (обычно в базовом Servlet-е) или в конце исполнения порождённого в Servlet-е потока. Но это нельзя делать и там и там одновременно. Иначе опять получим бардак в логах. Можно, конечно для части "асинхронных" сервлетов не вызывать flush() в базовом предке, например, ориентируясь на какой-то флаг, но это чистой воды костыль, т.к. требует от программиста помнить лишнее и подстраивать архитектуру под логику каждого частного случая. Мы сделаем аккуратнее.
Перепишем наш Logger, добавив в него Set для хранения id потоков, вывод из которых следует "приостановить":

import java.util.Map;
import java.util.concurrent.ConcurrentHashMap;
import java.util.concurrent.CopyOnWriteArraySet;
 
public class Logger {
 
 private static ConcurrentHashMap<Long, StringBuilder> data = new ConcurrentHashMap<Long, StringBuilder>();
    private static CopyOnWriteArraySet<Long> delayed = new CopyOnWriteArraySet<Long>();
    private static final String TAG = "MYTAG: ";
    private static final int MAX_TRACE_ELEMENTS = 5;
 
    public static void log(Object o) {
        Long id = getId();
        StringBuilder sb = data.get(id);
        if (sb==null) sb = new StringBuilder();
        if (o instanceof Exception) {
            Exception e = (Exception) o;
            e.printStackTrace();
            sb.append(TAG).append(e.getMessage()).append("\n");
            for (int i=0; i<MAX_TRACE_ELEMENTS; i++) {
                try {
                    sb.append(TAG).append(e.getStackTrace()[i].toString()).append("\n");
                } catch (IndexOutOfBoundsException ignored) {}
            }
        } else {
            System.err.println(o.toString());
            sb.append(TAG).append(o.toString()).append("\n");
        }
        data.put(id, sb);
    }
 
    public static void setDelayed(boolean isDelayed) {
        Long id = getId();
        if (isDelayed) delayed.add(id);
        else delayed.remove(id);
    }
 
    public static Long getId() {
        return Thread.currentThread().getId();
    }
 
    public static void flush() {
        flush(null);
    }
 
    public static void flush(Map<String, String> params) {
        Long id = getId();
        if (delayed.contains(id)) return;
        StringBuilder sb = data.get(id);
        if (sb!=null) {
            System.out.println("===================================>>>>>>");
            if (params!=null) {
                System.out.print("--------------");
                for (String key : params.keySet()) {
                    System.out.print("&"+key+"="+params.get(key));
                }
                System.out.println("--------------");
            }
            System.out.println(sb.toString());
            data.remove(id);
            System.out.println("<<<<<====================================");
        }
    }
}

Смысл тут в том, что для "приостановленных" потоков игнорируется вызов flush(). "Приостановку" устанавливаем и снимаем в нашем общем предке всех потоков, так что в самом проекте заботиться о порядке вызова flush() больше не нужно. Окончательно наш класс WorkerBased теперь выглядит так:

public abstract class WorkerBased extends Thread {
 
    private long id;
 
    public WorkerBased(long id) {
        this.id = id;
        Logger.setDelayed(true);
        this.start();
    }
 
    public abstract void process();
 
    @Override
    public void run() {
        process();
        Logger.setDelayed(false);
        Logger.flush();
    }
 
    @Override
    public long getId() {
        return this.id;
    }
}

Вывод
Всё по-прежнему просто: мы добавили всего один класс на полтора десятка строк и устранили достаточно неприятное ограничение нашей системы логирования. Теперь ей пользоваться ещё приятнее :)