1. 环境

Java: jdk1.8.0_144

2. 背景

Java多线程执行任务时，Logback输出的主线程和各个子线程的业务日志需要区分时，可以根据线程池和执行的线程来区分，但若要把它们联系起来只能根据时间线，既麻烦又无法保证准确性。

2018-10-27 23:09:22 [INFO][com.lxp.tool.log.LogAndCatchExceptionRunnableTest][main][testRun][38] -> test start
2018-10-27 23:09:22 [INFO][com.lxp.tool.log.RunnabeTestHelper][pool-1-thread-1][lambda$getRunnable$0][16] -> This is runnable.
2018-10-27 23:09:22 [INFO][com.lxp.tool.log.RunnabeTestHelper][pool-1-thread-2][lambda$getRunnable$0][16] -> This is runnable.
2018-10-27 23:09:22 [INFO][com.lxp.tool.log.RunnabeTestHelper][pool-1-thread-1][lambda$getRunnable$0][16] -> This is runnable.
2018-10-27 23:09:22 [INFO][com.lxp.tool.log.RunnabeTestHelper][pool-1-thread-2][lambda$getRunnable$0][16] -> This is runnable.
2018-10-27 23:09:22 [INFO][com.lxp.tool.log.RunnabeTestHelper][pool-1-thread-1][lambda$getRunnable$0][16] -> This is runnable.
2018-10-27 23:09:22 [INFO][com.lxp.tool.log.LogAndCatchExceptionRunnableTest][main][testRun][48] -> test finish

org.slf4j.MDC类提供了一个极好的解决方案，它可以为各个线程设置独有的上下文，当有必要时也可以把主线程的上下文复制给子线程，此时子线程可以拥有主线程+子线程的信息，在子线程退出前恢复到主线程上下文，如此一来，日志信息可以极大地便利定位问题，org.slf4j.MDC类在线程上下文切换上的应用记录本文的目的之一。
另一个则是过去一直被自己忽略的多线程时退出的问题，任务需要多线程执行有两种可能场景

• 多个任务互相独立，某个任务失败并不应该影响其它的任务继续执行
• 多个子任务组成一个完整的主任务，若某个子任务失败它应该直接退出，不需要等所有子任务完成

3. org.slf4j.MDC类在线程上下文切换时的应用

3.1 实现包装线程

• AbstractLogWrapper

public class AbstractLogWrapper<T> {private final T job;private final Map<?, ?> context;public AbstractLogWrapper(T t) {this.job = t;this.context = MDC.getCopyOfContextMap();}public void setLogContext() {if (this.context != null) {MDC.setContextMap(this.context);}}public void clearLogContext() {MDC.clear();}public T getJob() {return this.job;}
}

• LogRunnable

public class LogRunnable extends AbstractLogWrapper<Runnable> implements Runnable {public LogRunnable(Runnable runnable) {super(runnable);}@Overridepublic void run() {// 把主线程上下文复到子线程this.setLogContext();try {getJob().run();} finally {// 恢复主线程上下文this.clearLogContext();}}
}

• LogAndCatchExceptionRunnable

public class LogAndCatchExceptionRunnable extends AbstractLogWrapper<Runnable> implements Runnable {private static final Logger LOGGER = LoggerFactory.getLogger(LogAndCatchExceptionRunnable.class);public LogAndCatchExceptionRunnable(Runnable runnable) {super(runnable);}@Overridepublic void run() {// 把主线程上下文复到子线程this.setLogContext();try {getJob().run();} catch (Exception e) { // Catch所有异常阻止其继续传播LOGGER.error(e.getMessage(), e);} finally {// 恢复主线程上下文this.clearLogContext();}}
}

3.2 配置%X输出当前线程相关联的NDC

<?xml version="1.0" encoding="UTF-8"?>
<configuration><appender name="stdot" class="ch.qos.logback.core.ConsoleAppender"><layout class="ch.qos.logback.classic.PatternLayout"><pattern>%d{yyyy-MM-dd HH:mm:ss} [%p][%c][%t][%M][%L] %replace(Test_Method=%X{method} runn-able=%X{runn_able}){'.+=( |$)', ''} -> %m%n</pattern></layout></appender><root level="debug"><appender-ref ref="stdot"/></root>
</configuration>

3.3 配置线程相关信息并测试

class RunnabeTestHelper {private static final Logger LOGGER = LoggerFactory.getLogger(RunnabeTestHelper.class);private static final String RUNNABLE = "runn_able";static Runnable getRunnable() {return () -> {MDC.put(RUNNABLE, String.valueOf(System.currentTimeMillis()));LOGGER.info("This is runnable.");};}
}

• 测试方法

    @Testpublic void testRun() {try {MDC.put("method", "testRun");LOGGER.info("test start");LogAndCatchExceptionRunnable logRunnable = spy(new LogAndCatchExceptionRunnable(RunnabeTestHelper.getRunnable()));Set<String> set = new HashSet<>();doAnswer(invocation -> set.add(invocation.getMethod().getName())).when(logRunnable).setLogContext();doAnswer(invocation -> set.add(invocation.getMethod().getName())).when(logRunnable).clearLogContext();List<CompletableFuture<Void>> futures = IntStream.rangeClosed(0, 4).mapToObj(index -> CompletableFuture.runAsync(logRunnable, executorService)).collect(Collectors.toList());futures.forEach(CompletableFuture::join);assertEquals("[setLogContext, clearLogContext]", set.toString());LOGGER.info("test finish");} finally {MDC.clear();}}

• 测试结果

2018-11-01 01:08:04 [INFO][com.lxp.tool.log.LogRunnableTest][main][testRun][41]  -> test start
2018-11-01 01:08:05 [INFO][com.lxp.tool.log.RunnabeTestHelper][pool-1-thread-1][lambda$getRunnable$0][16] Test_Method=testRun runn-able=1541005685003 -> This is runnable.
2018-11-01 01:08:05 [INFO][com.lxp.tool.log.RunnabeTestHelper][pool-1-thread-1][lambda$getRunnable$0][16] Test_Method=testRun runn-able=1541005685004 -> This is runnable.
2018-11-01 01:08:05 [INFO][com.lxp.tool.log.RunnabeTestHelper][pool-1-thread-1][lambda$getRunnable$0][16] Test_Method=testRun runn-able=1541005685004 -> This is runnable.
2018-11-01 01:08:05 [INFO][com.lxp.tool.log.RunnabeTestHelper][pool-1-thread-2][lambda$getRunnable$0][16] Test_Method=testRun runn-able=1541005685003 -> This is runnable.
2018-11-01 01:08:05 [INFO][com.lxp.tool.log.RunnabeTestHelper][pool-1-thread-2][lambda$getRunnable$0][16] Test_Method=testRun runn-able=1541005685005 -> This is runnable.
2018-11-01 01:08:05 [INFO][com.lxp.tool.log.LogRunnableTest][main][testRun][50]  -> test finish

4. 多线程执行子线程出现异常时的处理

class RunnabeTestHelper {private static final Logger LOGGER = LoggerFactory.getLogger(RunnabeTestHelper.class);static Runnable getRunnable(AtomicInteger counter) {return () -> {try {Thread.sleep(1000);} catch (InterruptedException e) {LOGGER.error(e.getMessage(), e);}if (counter.incrementAndGet() == 2) {throw new NullPointerException();}LOGGER.info("This is {} runnable.", counter.get());};}static Runnable getRunnableWithCatchException(AtomicInteger counter) {return () -> {try {Thread.sleep(1000);if (counter.incrementAndGet() == 2) {throw new NullPointerException();}LOGGER.info("This is {} runnable.", counter.get());} catch (Exception e) {LOGGER.error("error", e);}};}
}

4.1 选择一：放充执行未执行的其它子线程

• 调用LogRunnable，允许子线程的异常继续传播

    @Testpublic void testRunnableWithoutCatchException() {Logger logger = Mockito.mock(Logger.class);AtomicInteger counter = new AtomicInteger(0);List<CompletableFuture<Void>> futures = IntStream.rangeClosed(0, 4).mapToObj(index -> CompletableFuture.runAsync(new LogRunnable(RunnabeTestHelper.getRunnable(counter)), executorService)).collect(Collectors.toList());try {futures.forEach(CompletableFuture::join);} catch (Exception e) {logger.error(e.getMessage(), e);}// 由于子线程的异常导致主线程退出，并不是所有任务都得到执行机会assertEquals(2, counter.get());verify(logger, Mockito.times(1)).error(anyString(), any(Throwable.class));}

4.2 选择二：执行完所有无异常的子线程

• 调用LogRunnable，在线程内部阻止异常扩散

    @Testpublic void testRunnableWithCatchException() {AtomicInteger counter = new AtomicInteger(0);List<CompletableFuture<Void>> futures = IntStream.rangeClosed(0, 4).mapToObj(index -> CompletableFuture.runAsync(new LogRunnable(RunnabeTestHelper.getRunnableWithCatchException(counter)), executorService)).collect(Collectors.toList());futures.forEach(CompletableFuture::join);// 由于子线程的异常被阻止，所有线程都得到执行机会assertEquals(5, counter.get());}

• 调用LogAndCatchExceptionRunnable，在包装类阻止异常扩散

    @Testpublic void testRunnableWithoutCatchException() {AtomicInteger counter = new AtomicInteger(0);List<CompletableFuture<Void>> futures = IntStream.rangeClosed(0, 4).mapToObj(index -> CompletableFuture.runAsync(new LogAndCatchExceptionRunnable(RunnabeTestHelper.getRunnable(counter)), executorService)).collect(Collectors.toList());futures.forEach(CompletableFuture::join);// 由于子线程的异常被阻止，所有线程都得到执行机会assertEquals(5, counter.get());}@Testpublic void testRunnableWithCatchException() {AtomicInteger counter = new AtomicInteger(0);List<CompletableFuture<Void>> futures = IntStream.rangeClosed(0, 4).mapToObj(index -> CompletableFuture.runAsync(new LogAndCatchExceptionRunnable(RunnabeTestHelper.getRunnableWithCatchException(counter)), executorService)).collect(Collectors.toList());futures.forEach(CompletableFuture::join);// 由于子线程的异常被阻止，所有线程都得到执行机会assertEquals(5, counter.get());}