Hatékony naplózás (log) Java 8-on [Szekesztve]

Először is készítsük el a kis naplózó rendszerünket.

class Logger {
    private static String loggedClassName;
    private final Class currentClass;

    public static void config(final String[] args) {
        if (args.length >= 1) {
            loggedClassName = args[0];
        }
    }

    public static Logger getLogger(final Class loggedClass) {
        return new Logger(loggedClass);
    }

    private Logger(final Class currentClass) {
        this.currentClass = currentClass;
    }

    public boolean isDebugEnabled() {
        boolean isEnabled = currentClass.getName().equals(loggedClassName);
        debugInternal("isDebugEnabled", "" + isEnabled);
        return currentClass.getName().equals(loggedClassName);
    }

    public void debug(final String method, final String message) {
        if (isDebugEnabled()) {
            debugInternal(method, message);
        }
    }

    private void debugInternal(final String method, final String message) {
        System.err.println("[" + currentClass.getName()
            + "." + method + "] " + message);
    }
}

Maximum egyetlen Logger osztály lehet aktív, amit a config függvény állít be az alkalmazás első argumentuma alapján.
A getLogger factory függvénnyel tudunk készíteni Logger példányt.
Az isDebugEnabled metódussal tudjuk ellenőrizni, hogy az adott osztálynál engedélyezve van-e a naplózás.
A debug metódussal tudunk naplózni, amennyiben az adott osztálynál engedélyezve van a naplózás.

Jöjjön a kis alkalmazásunk.

Az alkalmazásunk nagyon egyszerű lesz:

1. a stdin-t olvassuk,
2. a beolvasott szöveget számmá alakítjuk,
3. a számnak kiszámoljuk a négyzetét,
4. dekorálva szöveggé alakítjuk,
5. a stdout-ra kiírjuk.

class App {
    public static void main(final String[] args) {
        Logger.config(args);

        BufferedReader br = null;

        try {
            br = new BufferedReader(new InputStreamReader(System.in));
            while (true) {
                final String request = br.readLine();

                if (request == null) {
                    System.out.println("Exit!");
                    break;
                }
                final String response = Server.process(request);
                System.out.println(response);
            }

        } catch (IOException e) {
            e.printStackTrace();
        } finally {
            if (br != null) {
                try {
                    br.close();
                } catch (IOException e) {
                    e.printStackTrace();
                }
            }
        }
    }
}

Mint látható, nincs benne semmi extra, folyamatosan olvassuk a bemenetet (1.), a Server.process feldolgozza (2., 3., 4.), majd kiírjuk (5.).

Jöjjön az üzleti logika.

Nézzük a Server.process függvényt!

    public static String process(final String request) {
        final int number = Integer.parseInt(request);
        final int square = number * number;
        final String output = "Response: " + square;
        return output;
    }

Remekül működik is a programunk, megelégedve használják.

Hiba fellépése.

Ám egyszer csak hibát írnak fel, hogy bizonyos bemeneteket nem dolgoz fel a program, hanem időnként kilép.
A bemeneti állományt nem tudják ideadni, mert azt egy másik program generálja folyamatosan.
Ráadásul két-három napnyi folyamatos működés után áll le, így igen nagy terjedelmű is lenne.
Kitaláljuk, hogy a Server.process függvénybe teszünk naplózást, amiből majd rá fogunk jönni, hogy mi a baja.
Első körben naplózzuk ki a bemenő és a kimenő értéket.

    public static String process(final String request) {
        if (logger.isDebugEnabled()) {
            logger.debug("request: " + request);
        }

        final int number = Integer.parseInt(request);
        final int square = number * number;
        final String output = "Response: " + square;
        if (logger.isDebugEnabled()) {
            logger.debug("response: " + output);
        }

        return output;
    }

A logger.debug("request: " + request); önmagában nem jó, mivel ha a log nincs bekapcsolva az adott osztályra, a paraméter kiértékelése akkor is meg fog történni (a "request: " + request szöveg összefűzés), ezért a logger.isDebugEnabled-del le kell választanunk.
Sajnos a naplózás kikapcsolása esetén is le fog futni az logger.isDebugEnabled függvény hívás és kiértékelés.
Ráadásul kétszer. Ez utóbbit ki tudjuk úgy küszöbölni, hogy függvény elején elmentjük egy változóba és a végén is azt használjuk.
Vagy try-finally-ba rakjuk és egyben íratjuk ki a végén a request-et is.
Ha még megfejelnénk és az esetleges hibát is el akarnánk kapni és naplózni, valamint mérni szeretnénk egy-egy lefutás idejét is, akkor a szép kis pár soros üzleti logikánknak végképp búcsút vehetünk, ráadásul még a teljesítmény is visszaesik.
Ezt így nem küldhetjük ki az ügyfélnek! Mit tegyünk?

A Java 8 funkcionális újdonságai sietnek a segítségünkre.

Készítsünk egy kis függvényt, amely tetszőleges I -> O (I paramétert váró és O outputot adó) függvényt felokosít a naplózásra.
Lehetséges ez?
Igen, sőt minden földi jóval kiegészítheti, amit korábban bele szerettünk volna tenni (Exception elkapás és naplózás, időmérés).
Viszont a teljesítmény is visszafog akkor esni, ugye?
Naplózáskor egy kicsit igen, de ha ki van kapcsolva a naplózás, akkor semmi lassulás nem lesz!
Nézzük a varázs kódot :)

    public static <I, O> Function<I, O> makeLogged(
        final Class loggedClass,
        final String method,
        final Function<I, O> fn)
    {
        final Logger logger = Logger.getLogger(loggedClass);
        if (logger.isDebugEnabled()) {
            return new Function<I, O>() {
                public O apply(final I input) {
                    StringBuilder sb = new StringBuilder();

                    final long start = System.nanoTime();
                    sb.append("Input: ").append(input);
                    try {
                        final O output = fn.apply(input);
                        sb.append(". Output: ").append(output);
                        return output;
                    } catch(Exception e) {
                        sb.append(". Exception: ").append(e.getMessage());
                        throw e;
                    } finally {
                        final long end = System.nanoTime();
                        sb.append(". Running time: ")
                            .append((end - start))
                            .append(" ns");
                        logger.debugInternal(method, sb.toString());
                    }
                }
            };
        } else {
            return fn;
        }
    }

A Java miatt egy kicsit sok a boilerplate kód :(, de csak egyszer kell megírni és szinte soha nem kell majd olvasni :)
A működése röviden:

• Ha nincs engedélyezve a debug az adott osztályra, akkor a kapott függvényt adja vissza, így azt fogja használni a feldolgozáskor, így nem lehet semmilyen teljesítmény visszaesés.
• Ha engedélyezve van a log, akkor készít egy új függvényt,

  amiben elvégzi az időmérést, naplózza a ki- és a bemenet értékét, esetleges hibákat elkapja (tovább is dobja, hogy hibásan ne menjen a program) és azokat is naplózza.

Előnyei [Szerkesztve]:

1. Naplózáskor is gyorsabb ez a kód, mint ha kézzel az üzleti logikához tettük volna ezt, mivel itt meg tudjuk hívni a private debugInternal függvényt, ami nem ellenőrzi még egyszer, hogy engedélyezve van-e a logolás.
2. Összesen csak egyszer ellenőrzi a naplózás érvényességét, amikor létrehozza ezen új függvényt, a feldolgozáskor, ami sok milliószor lefut abban már nem.
3. További előnye, hogy az üzleti logikánk változatlan marad.
4. Ezzel az aspektus orientált programozással (AOP) tetszőleges I -> O függvényt fel lehet okosítani, akár olyanokat is, amiknek nincs meg a forrása.
5. Egyetlen egy helyen van a naplózás, ezért
   • ha új tudást akarunk a naplózásba tenni, akkor azt egyetlen helyen könnyedén meg tudjuk tenni és a változtatások minden naplózásnál megjelennek. (Pl. a bejelentkező személyét vagy a távoli gép IP címét is ki akarjuk íratni. Esetleges adatbázis lekérdezéseket, távoli szolgáltatásokat használhatunk a napló információk kiegészítésére.)
   • a naplózó tevékenységeket könnyedén párhuzamosíthatjuk, hogy ne terheljék a fő szál végrehajtását.
   • ha le akarjuk cserélni a naplózó rendszert egy másikra, akkor azt itt könnyedén meg tudjuk tenni.
6. Nincs függőség a naplózandó és a naplózó rendszer között. Ha az üzleti logikánkba (elejére, végére) tesszük a naplózást, akkor vagy erős függőség lesz a naplózó rendszerrel vagy megoldhatjuk Dependency Injection-nel, akkor gyenge függőség lesz köztük. Ezeknél csak az a jobb, ha nincs függőség, mert akkor szabadon cserélhetők/módosíthatók egymástól függetlenül, illetve könnyebben felhasználhatók, tesztelhetők (nem kell mock és hasonlók), olvashatók és karbantarthatók.

Használata roppant egyszerű, a feldolgozó ciklus előtt készíttetünk egy naplózással felokosított feldolgozó függvényt:

    final Function<String, String> process = Logger.makeLogged(
        App.class, "process", Server::process);

Majd a feldolgozásban kicseréljük a Server.process függvény hívását az új feldolgozó függvény hívására process.apply.

Példa helyes bemenetre:

[error] [log.App.process] Input: 23. Output: Response: 529. Running time: 182127 ns 

Példa hibás bemenetre:

[error] [log.App.process] Input: ser. Exception: For input string: "ser". Running time: 160540 ns

A forrás elérhető itt.
(Scala Build Tool-lal könnyen fordítható, futtatható)