MDC naplózáskor és distributed tracing

2021. október 4.

A naplózó keretrendszerekben (legalábbis a Log4J-ben és a Logbackben) elég régóta ott a Mapped Diagnostic Context, ami egy nagyon hasznos eszköz, mégis aránylag ritkán látom használni.

Egy terhelés alatt lévő webes alkalmazásnál a naplóbejegyzéseket alapvetően elég nehéz szétválogatni pl. kérésenként, sessionönként/felhasználónként. Az MDC segítségével minden napló bejegyzésbe elhelyezhetük olyan adatot (pl. session azonosítót, felhasználónevet), mely ezek azonosítását teszi lehetővé. Ráadásul tehetjük ezt anélkül, hogy a naplózás helyén a hívást, és benne az üzenetet módosítanunk kéne.

A naplóüzenetek címkézése, azonosítása különösen fontos lehet elosztott, microservice környezetben, ahol különböző gépekről beérkező naplóüzeneteket kell összekötnünk.

A megvalósítás egyszerű, az MDC-t úgy képzeljük el, mint egy mapet, ami az adott szálhoz van kötve. Ebbe a mapben helyezhetünk el értékeket, melyek egész addig ott lesznek, míg a szál el nem végezte a feladatát. Utána egyszerűen konfigurálhatjuk, hogy ezek az értékek jelenjenek meg minden naplóüzenetben. A szálhoz kötés egy ThreadLocal példánnyal történik.

Egyszerű alkalmazásban

Mivel az MDC a Log4J-ben és a Logbackben is elérhető, az SLF4J is tartalmazza. Mivel különösen webes alkalmazásnál hasznos, én egy Spring Bootos alkalmazással fogom bemutatni, amiben Logback az alapértelmezett naplózó implementáció. Ettől függetlenül mindenütt használható, ahol naplózás van.

A példa projekt elérhető a GitHubon.

Az MDC-be értéket betenni a következőképp lehet:

MDC.put("username", "johndoe");

Utána már csak az application.properties fájlban (, vagy ha több mindent szeretnénk megadni, akkor a Logback konfigurációs XML fájljában) kell konfigurálni a layoutot:

logging.pattern.console = %d{HH:mm:ss.SSS} [%thread] [%X{username}] %-5level %logger{36} - %msg%n

Látható, hogy a %X{username} részlet írja ki a bejelentkezett felhasználót minden napló bejegyzés esetén. Azaz legyen a hívás a következő.

log.info("Hello Spring Boot");

A hozzá tartozó naplóbejegyzés:

16:33:38.349 [http-nio-8080-exec-1] [johndoe] INFO  hello.HelloController - Hello Spring Boot

Figyeljük meg a példában, hogy egy Spring MVC controllerből naplózunk, és a log attribútumot a Lombok @Slf4j annotáció hozza létre.

@RestController
@Slf4j
public class HelloController {

    @GetMapping("hello")
    public String sayHello() {
        log.info("Hello Spring Boot");
        return "Hello Spring Boot";
    }

}

Ez jó, ha van felhasználónk, de mi van akkor, ha a különböző http kérésekhez tartozó napló üzeneteket szeretnénk megkülönböztetni? Ekkor érdemes minden kéréshez gyártani egy egyedi azonosítót, legyen ez a tracking id, és egy Servlet Filterrel tegyük ezt meg, minden bejövő http kérésnél.

@Component
public class TraceFilter extends OncePerRequestFilter {

    public static final String TRACE_ID_MDC_KEY = "traceId";

    @Override
    protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain) 
            throws ServletException, IOException {
        var traceId = UUID.randomUUID().toString();
        MDC.put(TRACE_ID_MDC_KEY, traceId);

        try {
            filterChain.doFilter(request, response);
        } finally {
            MDC.remove(TRACE_ID_MDC_KEY);
        }

    }
}

Figyeljük meg, hogy a Springben lévő OncePerRequestFilter az ősosztály, ami kérésenként egyszer fut csak le. (Ezt egy request attribute-tal oldja meg.)

Ennek megfelelően a módosított pattern a következő.

logging.pattern.console = %d{HH:mm:ss.SSS} [%thread] [%X{traceId}] %-5level %logger{36} - %msg%n

És a kiírt napló üzenet egy generált UUID-t tartalmaz.

16:33:38.349 [http-nio-8080-exec-1] [84cb2c52-c021-41e0-bddb-a9c53472a550] INFO  hello.HelloController - Hello Spring Boot

Észrevehetjük, hogy a REST webszolgáltatások tesztelésére használt Postman is küld egy egyedi azonosítót kérésenként Postman-Token http headerben. Ez jól használható teszteléskor, hogy meg tudjuk feleltetni a naplóüzeneteket a kéréseinknek. (Amúgy az említett header azért került bele, mert a Chrome-ban volt egy bug, a http kérések kezelésében. Ha elküldött egy http kérést, és ha közben ugyanazokkal a paraméterekkel elküldött egy másikat is, akkor ha az első visszatért, akkor annak válaszát adta vissza a második válaszaként is. Ha viszont akár csak a headerben is különböztek, már a második választ adta vissza a második hívás válaszaként.)

Módosítsuk a filtert, hogy vegye ki ezt a headert, tegye át az MDC-be, és írja ki a naplóba.

@Component
public class TraceFilter extends OncePerRequestFilter {

    public static final String TRACE_ID_MDC_KEY = "traceId";

    public static final String POSTMAN_TOKEN_MDC_KEY = "postmanToken";

    public static final String POSTMAN_TOKEN_HEADER_NAME = "Postman-Token";

    @Override
    protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain) 
            throws ServletException, IOException {
        var traceId = UUID.randomUUID().toString();
        var postmanToken = request.getHeader(POSTMAN_TOKEN_HEADER_NAME);
        var userAgent = request.getHeader(USER_AGENT_HEADER_NAME);

        MDC.put(TRACE_ID_MDC_KEY, traceId);
        MDC.put(POSTMAN_TOKEN_MDC_KEY, postmanToken);

        try {
            filterChain.doFilter(request, response);
        } finally {
            MDC.remove(TRACE_ID_MDC_KEY);
            MDC.remove(POSTMAN_TOKEN_MDC_KEY);
        }

    }
}

A módosított pattern a következő.

logging.pattern.console = %d{HH:mm:ss.SSS} [%thread] [%X{traceId},%X{postmanToken}] %-5level %logger{36} - %msg%n

És a kiírt napló üzenet.

16:33:38.349 [http-nio-8080-exec-1] [84cb2c52-c021-41e0-bddb-a9c53472a550,1e8653f5-83f6-4bb0-9d45-004af1867763] INFO  hello.HelloController - Hello Spring Boot

Ahol az első UUID a szerver által kiosztott trace id, a második pedig a Postman által küldött Postman Token.

A Logback érdekes tulajdonsága, hogy különböző filtereket lehet definiálni, ezzel szűrni a naplóüzeneteket. Módosítsuk a filterünket, hogy ne csak a Postman-Token értekét vegye ki a headerből, hanem a User-Agent értékét is, majd szintén tegye át az MDC-be.

Ezután pl. ez alapján a MDCFilter-rel tudunk szűrni. Ehhez viszont már nem elegendő az application.properties állomány, hanem saját xml konfigurációt kell alkalmazni. Viszont ezt meg kell adni az application.properties fájlban.

logging.config = classpath:hello-logback.xml

És a hello-logback.xml tartalma a következő.

<?xml version="1.0" encoding="UTF-8"?>
<configuration>

    <property name="CONSOLE_LOG_PATTERN" value="%d{HH:mm:ss.SSS} [%thread] [%X{traceId},%X{postmanToken}] %-5level %logger{36} - %msg%n"/>

    <include resource="org/springframework/boot/logging/logback/defaults.xml"/>
    <include resource="org/springframework/boot/logging/logback/console-appender.xml"/>

    <turboFilter class="ch.qos.logback.classic.turbo.MDCFilter">
        <MDCKey>userAgent</MDCKey>
        <Value>PostmanRuntime/7.28.4</Value>
        <OnMatch>DENY</OnMatch>
    </turboFilter>

    <root level="INFO">
        <appender-ref ref="CONSOLE"/>
    </root>

</configuration>

Itt is látható egy kis Logback + Spring Bootos trükk, hogy include-áljuk a default konfigot a defaults.xml és console-appender.xml állományokból. (Valamint nagyon fontos megjegyzés, hogy ezekben az xml állományokban akár environment property-ket is alkalmazhatunk, ami különösen hasznos lehet, ha az alkalmazásunkat pl. Docker konténerben futtatjuk. Ekkor a ${USERAGENT_PREFIX} formátumot használhatjuk.)

Az MDCFilter csak pontos egyezőséget képes vizsgálni. Saját filter implementálása gyerekjáték.

public class UserAgentMdcFilter extends TurboFilter {

    private String prefix;

    @Override
    public FilterReply decide(Marker marker, Logger logger, Level level, String format, Object[] params, Throwable t) {
        var userAgent = MDC.get(TraceFilter.USER_AGENT_MDC_KEY);
        if (userAgent != null && userAgent.toLowerCase().startsWith(prefix.toLowerCase())) {
            return FilterReply.DENY;
        }
        return FilterReply.NEUTRAL;
    }

    public void setPrefix(String prefix) {
        this.prefix = prefix;
    }
}

A DENY azt jelenti, hogy a naplóbeüzenetet ki kell szűrni. További értékei a NEUTRAL, amikor további filterek dönthetnek, vagy a ACCEPT, amikor a naplóüzenet azonnal kiírható.

Az ehhez tartozó xml konfiguráció olvasható alább.

<turboFilter class="hello.UserAgentMdcFilter">
    <prefix>PostmanRuntime</prefix>
</turboFilter>

Látható, hogy milyen elegáns a konfiguráció is, hiszen csak egy settert kellett definiálni.

Microservice környezetben

Microservice környezetben kihívást okozhat a különböző microservice-ek által beküldött naplóüzenetek összepárosítása. Képzeljük el, hogy az A microservice hívja a B-t, és az a C-t, és szeretnénk a kéréshez tartozó, de az összes rendszerben keletkezett naplóüzeneteket egyben látni.

Erre való a Distributed tracing minta. Az alapötlet ugyanaz. A kéréshez társítsunk egy azonosítót (elnevezési konvenció szerint tracing id), valamint minden rendszerben végrehajtott egy vagy több művelet kapjon szintén egy egyedi azonosítót (elnevezési konvenció szerint span id). Ezek a spanek hierarchiába rendezhetők, hiszen az A rendszerben a kérés kapott egy A-1 span id-t, ez továbbhívott a B rendszerbe, átadva ez az id-t, és az ott végrehajtott művelet kapot egy B-1 id-t. A B-1 spannek az A-1 a szülője.

Más nevezéktanban correlation id-ként hivatkoznak a rendszereken átívelő azonosítóra.

Ahhoz, hogy ez működjön, ezeket az azonosítókat az első hívás helyén ki kell osztani, ki kell naplózni (ehhez nagyon jól jön a fent említett MDC), és tovább kell adni, és a továbbadottat ki is kell olvasni. Ezek programozása nem nagy kihívás, talán a továbbadás lehet érdekesebb. Ez REST hívás esetén lehet http headerben, aszinkron üzenetek küldése esetén lehet az üzenet fejlécében.

Azonban, hogy ne kelljen ezt nekünk magunk implementálni, Spring Boot alkalmazásban használhatjuk a Spring Cloud Sleuth projektet. Ez létrehoz egy beant, melyet lehet aztán injektálni, és programozottan elindíthatunk és leállíthatunk egy spant, és természetesen elvégzi az azonosítók generálását is (még API is van rá, ez az OpenTracing API). Valamint ezeket az azonosítókat a naplóüzenetekben is elhelyezi (MDC használatával). Alkalmazhatunk deklaratív konfigurációt is annotációk használatával. De a legnagyobb ereje talán abban van, hogy különböző eszközökhöz implementálva van ezen azonosítók továbbadása, azaz a propagáció. Erre több mechanizmus is van, pl. AWS, B3, W3C. A B3 pl. a specifikáció alapján nagyon egyszerű:

X-B3-TraceId: 80f198ee56343ba864fe8b2a57d3eff7
X-B3-ParentSpanId: 05e3ac9a4f6e3b90
X-B3-SpanId: e457b5a2e4d86bd1
X-B3-Sampled: 1

Ha ezt http headerben, vagy üzenet headerben szeretnénk továbbadni, nem kell magunknak megoldanunk, mert a Spring Cloud Sleuth tartalmaz integrációt a következő eszközökhöz: Rest Template, WebClient, RabbitMQ, Kafka, JMS, OpenFeign, stb.

Ezzel már megtörténik az id generálás, propagáció, a propagált beolvasása is, a naplózás. Már csak meg kéne jeleníteni. Erre való Zipkin, aminek http-n,
Kafkán, vagy bármilyen soron keresztül is képes továbbítani az adatokat.

A Zipkin grafikusan tudja megjeleníteni a trace-hez tartozó spaneket, az idő függvényében.

Zipkin