Wie kann man MDC mit Thread-Pools verwenden?

Question

In unserer Software verwenden wir ausgiebig MDC um Dinge wie Sitzungs-IDs und Benutzernamen für Webanfragen zu verfolgen. Dies funktioniert gut, solange es im ursprünglichen Thread läuft.

Allerdings gibt es eine Menge Dinge, die im Hintergrund verarbeitet werden müssen. Dafür verwenden wir die java.concurrent.ThreadPoolExecutor y java.util.Timer Klassen zusammen mit einigen selbstgedrehten asynchron Ausführungsdienstleistungen. Alle diese Dienste verwalten ihren eigenen Thread-Pool.

Das ist es, was Handbuch von Logback über die Verwendung von MDC in einer solchen Umgebung zu sagen hat:

Eine Kopie des zugeordneten Diagnosekontextes kann nicht immer vom initiierenden Thread an Worker-Threads vererbt werden. Dies ist der Fall, wenn java.util.concurrent.Executors für das Thread-Management verwendet wird. Die Methode newCachedThreadPool beispielsweise erstellt einen ThreadPoolExecutor und verfügt wie anderer Thread-Pooling-Code über eine komplizierte Thread-Erstellungslogik.

In solchen Fällen wird empfohlen, dass MDC.getCopyOfContextMap() auf dem ursprünglichen (Master-)Thread aufgerufen wird, bevor eine Aufgabe an den Executor übergeben wird. Wenn die Aufgabe läuft, sollte sie als erste Aktion MDC.setContextMapValues() aufrufen, um die gespeicherte Kopie der ursprünglichen MDC-Werte mit dem neuen vom Executor verwalteten Thread zu verknüpfen.

Das wäre in Ordnung, aber man vergisst sehr leicht, diese Anrufe hinzuzufügen, und es gibt keine einfache Möglichkeit, das Problem zu erkennen, bevor es zu spät ist. Das einzige Anzeichen mit Log4j ist, dass Sie fehlende MDC-Informationen in den Protokollen erhalten, und mit Logback erhalten Sie veraltete MDC-Informationen (da der Thread im Tread-Pool sein MDC von der ersten Aufgabe erbt, die auf ihm ausgeführt wurde). Beides sind ernste Probleme in einem Produktionssystem.

Ich sehe unsere Situation in keiner Weise als etwas Besonderes an, aber ich konnte im Internet nicht viel über dieses Problem finden. Offenbar sind nicht viele Menschen mit diesem Problem konfrontiert, also muss es eine Möglichkeit geben, es zu vermeiden. Was machen wir hier falsch?

Answer 1

Ja, das ist ein häufiges Problem, das ich auch schon hatte. Es gibt ein paar Umgehungsmöglichkeiten (z. B. die manuelle Einstellung, wie beschrieben), aber im Idealfall möchten Sie eine Lösung, die

• Stellt den MDC konsistent ein;
• Vermeidung von stillschweigenden Fehlern, bei denen die MDC falsch ist, ohne dass Sie es wissen; und
• Minimiert die Änderungen bei der Verwendung von Thread-Pools (z. B. Unterklassenbildung Callable con MyCallable überall, oder ähnliche Hässlichkeit).

Hier ist eine Lösung, die ich verwende und die diese drei Anforderungen erfüllt. Der Code sollte selbsterklärend sein.

(Nebenbei bemerkt, kann dieser Executor erstellt und an Guava's MoreExecutors.listeningDecorator() , wenn Sie Guava's ListanableFuture .)

import org.slf4j.MDC;

import java.util.Map;
import java.util.concurrent.*;

/**
 * A SLF4J MDC-compatible {@link ThreadPoolExecutor}.
 * <p/>
 * In general, MDC is used to store diagnostic information (e.g. a user's session id) in per-thread variables, to facilitate
 * logging. However, although MDC data is passed to thread children, this doesn't work when threads are reused in a
 * thread pool. This is a drop-in replacement for {@link ThreadPoolExecutor} sets MDC data before each task appropriately.
 * <p/>
 * Created by jlevy.
 * Date: 6/14/13
 */
public class MdcThreadPoolExecutor extends ThreadPoolExecutor {

    final private boolean useFixedContext;
    final private Map<String, Object> fixedContext;

    /**
     * Pool where task threads take MDC from the submitting thread.
     */
    public static MdcThreadPoolExecutor newWithInheritedMdc(int corePoolSize, int maximumPoolSize, long keepAliveTime,
                                                            TimeUnit unit, BlockingQueue<Runnable> workQueue) {
        return new MdcThreadPoolExecutor(null, corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue);
    }

    /**
     * Pool where task threads take fixed MDC from the thread that creates the pool.
     */
    @SuppressWarnings("unchecked")
    public static MdcThreadPoolExecutor newWithCurrentMdc(int corePoolSize, int maximumPoolSize, long keepAliveTime,
                                                          TimeUnit unit, BlockingQueue<Runnable> workQueue) {
        return new MdcThreadPoolExecutor(MDC.getCopyOfContextMap(), corePoolSize, maximumPoolSize, keepAliveTime, unit,
                workQueue);
    }

    /**
     * Pool where task threads always have a specified, fixed MDC.
     */
    public static MdcThreadPoolExecutor newWithFixedMdc(Map<String, Object> fixedContext, int corePoolSize,
                                                        int maximumPoolSize, long keepAliveTime, TimeUnit unit,
                                                        BlockingQueue<Runnable> workQueue) {
        return new MdcThreadPoolExecutor(fixedContext, corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue);
    }

    private MdcThreadPoolExecutor(Map<String, Object> fixedContext, int corePoolSize, int maximumPoolSize,
                                  long keepAliveTime, TimeUnit unit, BlockingQueue<Runnable> workQueue) {
        super(corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue);
        this.fixedContext = fixedContext;
        useFixedContext = (fixedContext != null);
    }

    @SuppressWarnings("unchecked")
    private Map<String, Object> getContextForTask() {
        return useFixedContext ? fixedContext : MDC.getCopyOfContextMap();
    }

    /**
     * All executions will have MDC injected. {@code ThreadPoolExecutor}'s submission methods ({@code submit()} etc.)
     * all delegate to this.
     */
    @Override
    public void execute(Runnable command) {
        super.execute(wrap(command, getContextForTask()));
    }

    public static Runnable wrap(final Runnable runnable, final Map<String, Object> context) {
        return new Runnable() {
            @Override
            public void run() {
                Map previous = MDC.getCopyOfContextMap();
                if (context == null) {
                    MDC.clear();
                } else {
                    MDC.setContextMap(context);
                }
                try {
                    runnable.run();
                } finally {
                    if (previous == null) {
                        MDC.clear();
                    } else {
                        MDC.setContextMap(previous);
                    }
                }
            }
        };
    }
}

Answer 2

Wir sind auf ein ähnliches Problem gestoßen. Vielleicht möchten Sie ThreadPoolExecutor erweitern und die Methoden before/afterExecute überschreiben, um die benötigten MDC-Aufrufe vor dem Starten/Stoppen neuer Threads durchzuführen.

Answer 3

IMHO ist das die beste Lösung:

• utiliser ThreadPoolTaskExecutor
• Ihr eigenes System einführen TaskDecorator
• es verwenden: executor.setTaskDecorator(new LoggingTaskDecorator());

Der Dekorateur kann wie folgt aussehen:

private final class LoggingTaskDecorator implements TaskDecorator {

    @Override
    public Runnable decorate(Runnable task) {
        // web thread
        Map<String, String> webThreadContext = MDC.getCopyOfContextMap();
        return () -> {
            // work thread
            try {
                // TODO: is this thread safe?
                MDC.setContextMap(webThreadContext);
                task.run();
            } finally {
                MDC.clear();
            }
        };
    }

}

Answer 4

So mache ich es mit festen Thread-Pools und Executors:

ExecutorService executor = Executors.newFixedThreadPool(4);
Map<String, String> mdcContextMap = MDC.getCopyOfContextMap();

Im Einfädelteil:

executor.submit(() -> {
    MDC.setContextMap(mdcContextMap);
    // my stuff
});

Answer 5

Falls Sie dieses Problem in einer Spring-Framework-Umgebung haben, in der Sie Aufgaben mit Hilfe von @Async Annotation können Sie die Aufgaben mit Hilfe der TaskDecorator Ansatz.

Ein Beispiel für die Vorgehensweise finden Sie hier:

• Frühling 4.3: Verwendung eines TaskDecorators zum Kopieren von MDC-Daten in @Async Threads

Ich war mit diesem Problem konfrontiert und der obige Artikel hat mir geholfen, es zu lösen.