From 3de22ffba3c5325f29c39b66c0c8a02e2d86f9e4 Mon Sep 17 00:00:00 2001 From: Dennis C Date: Fri, 5 May 2023 01:43:34 +0200 Subject: [PATCH] Collect and log exceptions occurring in DeferredWorkQueue tasks (#9449) --- .../minecraftforge/fml/DeferredWorkQueue.java | 51 +++++++++++++++-- .../debug/DeferredWorkQueueTest.java | 56 +++++++++++++++++++ src/test/resources/META-INF/mods.toml | 2 + 3 files changed, 103 insertions(+), 6 deletions(-) create mode 100644 src/test/java/net/minecraftforge/debug/DeferredWorkQueueTest.java diff --git a/fmlcore/src/main/java/net/minecraftforge/fml/DeferredWorkQueue.java b/fmlcore/src/main/java/net/minecraftforge/fml/DeferredWorkQueue.java index 5579704dad..b8e918316f 100644 --- a/fmlcore/src/main/java/net/minecraftforge/fml/DeferredWorkQueue.java +++ b/fmlcore/src/main/java/net/minecraftforge/fml/DeferredWorkQueue.java @@ -11,9 +11,11 @@ import java.util.HashMap; import java.util.Map; import java.util.Optional; import java.util.concurrent.CompletableFuture; +import java.util.concurrent.CompletionException; import java.util.concurrent.ConcurrentLinkedDeque; import java.util.concurrent.Executor; import java.util.concurrent.TimeUnit; +import java.util.function.Function; import java.util.function.Supplier; import com.google.common.base.Stopwatch; @@ -53,17 +55,29 @@ public class DeferredWorkQueue public void runTasks() { if (tasks.isEmpty()) return; LOGGER.debug(LOADING, "Dispatching synchronous work for work queue {}: {} jobs", modLoadingStage, tasks.size()); + RuntimeException aggregate = new RuntimeException(); Stopwatch timer = Stopwatch.createStarted(); - tasks.forEach(t->makeRunnable(t, Runnable::run)); + tasks.forEach(t -> makeRunnable(t, Runnable::run, aggregate)); timer.stop(); - LOGGER.debug(LOADING, "Synchronous work queue completed in {}", timer); + if (aggregate.getSuppressed().length > 0) { + LOGGER.fatal( + LOADING, + "Synchronous work queue completed exceptionally in {}, see suppressed exceptions for details:", + timer, + aggregate + ); + //TODO 1.20: throw aggregate exception + } else { + LOGGER.debug(LOADING, "Synchronous work queue completed in {}", timer); + } } - private static void makeRunnable(TaskInfo ti, Executor executor) { + private static void makeRunnable(TaskInfo ti, Executor executor, RuntimeException aggregate) { executor.execute(() -> { Stopwatch timer = Stopwatch.createStarted(); ModLoadingContext.get().setActiveContainer(ti.owner); try { + ti.future.exceptionally(t -> captureException(ti.owner.getModId(), aggregate, t)); ti.task.run(); } finally { ModLoadingContext.get().setActiveContainer(null); @@ -75,13 +89,38 @@ public class DeferredWorkQueue }); } + private static T captureException(String modId, RuntimeException aggregate, Throwable throwable) { + if (throwable instanceof CompletionException ce) { + throwable = ce.getCause(); + } + aggregate.addSuppressed(throwable); + LOGGER.error("Mod '{}' encountered an error in a deferred task:", modId, throwable); + return null; + } + public CompletableFuture enqueueWork(final ModContainer modInfo, final Runnable work) { - return CompletableFuture.runAsync(work, r->tasks.add(new TaskInfo(modInfo, r))); + return enqueueWork(modInfo, taskInfo -> CompletableFuture.runAsync(work, r -> taskInfo.task = r)); } public CompletableFuture enqueueWork(final ModContainer modInfo, final Supplier work) { - return CompletableFuture.supplyAsync(work, r->tasks.add(new TaskInfo(modInfo, r))); + return enqueueWork(modInfo, taskInfo -> CompletableFuture.supplyAsync(work, r -> taskInfo.task = r)); } - record TaskInfo(ModContainer owner, Runnable task) {} + private CompletableFuture enqueueWork(final ModContainer modInfo, Function> futureGen) { + TaskInfo taskInfo = new TaskInfo(modInfo); + CompletableFuture future = futureGen.apply(taskInfo); + taskInfo.future = future; + tasks.add(taskInfo); + return future; + } + + private static class TaskInfo { + private final ModContainer owner; + private Runnable task; + private CompletableFuture future; + + private TaskInfo(ModContainer owner) { + this.owner = owner; + } + } } \ No newline at end of file diff --git a/src/test/java/net/minecraftforge/debug/DeferredWorkQueueTest.java b/src/test/java/net/minecraftforge/debug/DeferredWorkQueueTest.java new file mode 100644 index 0000000000..13c04ea148 --- /dev/null +++ b/src/test/java/net/minecraftforge/debug/DeferredWorkQueueTest.java @@ -0,0 +1,56 @@ +/* + * Copyright (c) Forge Development LLC and contributors + * SPDX-License-Identifier: LGPL-2.1-only + */ + +package net.minecraftforge.debug; + +import com.mojang.logging.LogUtils; +import net.minecraftforge.eventbus.api.SubscribeEvent; +import net.minecraftforge.fml.common.Mod; +import net.minecraftforge.fml.event.lifecycle.FMLCommonSetupEvent; +import org.slf4j.Logger; + +/** + * Tests that the {@link net.minecraftforge.fml.DeferredWorkQueue} properly executes enqueued tasks and + * forwards any exceptions thrown by those tasks + */ +@Mod(DeferredWorkQueueTest.MOD_ID) +@Mod.EventBusSubscriber(modid = DeferredWorkQueueTest.MOD_ID, bus = Mod.EventBusSubscriber.Bus.MOD) +public class DeferredWorkQueueTest +{ + public static final String MOD_ID = "deferred_work_queue_test"; + private static final boolean ENABLE = false; + private static final Logger LOGGER = LogUtils.getLogger(); + + public DeferredWorkQueueTest() { } + + @SubscribeEvent + public static void onCommonSetup(final FMLCommonSetupEvent event) + { + if (!ENABLE) + { + return; + } + + event.enqueueWork(() -> LOGGER.info("Enqueued runnable ran")); + event.enqueueWork(() -> "Enqueued supplier ran").thenAccept(LOGGER::info); + + event.enqueueWork(DeferredWorkQueueTest::executeThrowingRunnable); + event.enqueueWork(DeferredWorkQueueTest::executeThrowingSupplier).thenAccept(s -> + LOGGER.error("This must not be printed") + ); + } + + private static void executeThrowingRunnable() + { + LOGGER.info("Enqueued throwing runnable ran"); + throw new IllegalStateException("Throwing runnable ran"); + } + + private static String executeThrowingSupplier() + { + LOGGER.info("Enqueued throwing supplier ran"); + throw new IllegalStateException("Throwing supplier ran"); + } +} diff --git a/src/test/resources/META-INF/mods.toml b/src/test/resources/META-INF/mods.toml index b96b362222..8a1fe56f7d 100644 --- a/src/test/resources/META-INF/mods.toml +++ b/src/test/resources/META-INF/mods.toml @@ -26,6 +26,8 @@ modId="mdk_datagen" modId="shader_resources_test" [[mods]] modId="crash_callable_test" +[[mods]] + modId="deferred_work_queue_test" # LEGACY TEST CASES ###### The mods below are from the old test framework and need to be yeeted later again.