scijava / scijava-common

A plugin framework and application container with built-in extensibility mechanism :electric_plug:
BSD 2-Clause "Simplified" License
87 stars 52 forks source link

Exceptions during module execution are never retrieved from the FutureTask #452

Closed NicoKiaru closed 1 year ago

NicoKiaru commented 1 year ago

If a Scijava Command fails, and throws for instance a RuntimeException, then no error shows up anywhere.

I suspect it's because of the try{} finally{} statements of the DefaultThreadService, which are lacking a catch block (at two places):

https://github.com/scijava/scijava-common/blob/fe8297f49a35a286792a30519955acfa03882be2/src/main/java/org/scijava/thread/DefaultThreadService.java#L213

ping @tpietzsch and @tischi, which found also this issue during the hackathon in Milano

ctrueden commented 1 year ago

Thanks for the report, @NicoKiaru. But try/finally does not actually prevent exceptions from being thrown—it just performs the finally block before throwing the exception. So the problem must be somewhere else.

ctrueden commented 1 year ago

The following code works (in the sense that the exception is unhandled and prints to the console):

import org.scijava.thread.ThreadService;

public class Main {
    public static void main(String[] args) throws Exception {
        Runnable r = () -> {
            throw new RuntimeException("I'm a failure");
        };
        Thread t = new Thread(r);
        t.start();
        t.join();
    }
}

Similarly, the following code also "works":

import org.scijava.thread.ThreadService;

public class Main {
    public static void main(String[] args) throws Exception {
        Runnable r = () -> {
            throw new RuntimeException("I'm a failure");
        };
        Context ctx = new Context();
        ThreadService ts = ctx.service(ThreadService.class);
        ts.invoke(r);
        Thread.sleep(500);
        ctx.dispose();
    }
}

However, the following code "fails" as described in this issue:

import org.scijava.command.Command;
import org.scijava.command.CommandInfo;
import org.scijava.command.CommandService;
import org.scijava.plugin.PluginIndex;

public class Main implements Command {

    @Override
    public void run() {
        System.out.println("Doing the thing...");
        if (true) throw new RuntimeException("I'm a failure");
        System.out.println("I did the thing.");
    }

    public static void main(String[] args) throws Exception {
        // Because I hate annotation processing.
        PluginIndex pluginIndex = new PluginIndex();
        CommandInfo info = new CommandInfo(Main.class);
        pluginIndex.add(info);

        // Run the command.
        try (Context ctx = new Context(pluginIndex)) {
            CommandService cs = ctx.service(CommandService.class);
            cs.run(Main.class, true);
            Thread.sleep(500);
        }
    }
}

So something inside the module execution framework is eating the exception.

ctrueden commented 1 year ago

I tried adding:

ctx.service(LogService.class).setLevel(LogLevel.DEBUG);

just before calling cs.run, but even then, no exception is printed. :frowning:

ctrueden commented 1 year ago

OK, I debugged into it, and it's because of this code in FutureTask:

} catch (Throwable ex) {
  result = null;
  ran = false;
  setException(ex);
}

Which led me to understand that the exception, which happens on a different thread, is stored by the Future, such that when you ask for the result by calling get(), it will be thrown to the calling thread then.

So, you can avoid this problem by writing:

cs.run(Main.class, true).get();

instead of:

cs.run(Main.class, true);

Or of course doing the get() later, if you need the asynchronous behavior initially.

But if you never call get(), you'll never get the exception. :clown_face: I'm here all week.

NicoKiaru commented 1 year ago

Thanks for looking into that! What happens when a command is launched through the GUI ? get() is never called, right?

I think that's where the issue is the most annoying: you start a plugin in the GUI, but nothing is happening without any error message. I'll try to make a minimal example

ctrueden commented 1 year ago

@NicoKiaru I agree that never seeing these exceptions in the UI is a problem. I renamed this issue to reflect our findings so far, and reopened it. The first idea I have to fix it would be to change the ModuleRunner somehow... maybe put a try/catch around the module.run() line, catch all throwables, and call es.publish(new ModuleFailedEvent(module)) (which we'd have to invent), and then rethrow the exception afterward. Then even if get() is never called, services could still be informed of the failure, and do something with the exception.

NicoKiaru commented 1 year ago

Hmm indeed that's much harder than what I've thought...

ctrueden commented 1 year ago

I'm reopening this. The work that @gselzer did with #459 is a big step forward toward solving this: it adds a ModuleErroredEvent that gets published when the ModuleRunner execution fails. But by default, nothing in the framework subscribes to this event, and so module errors are still eaten and invisible. We need to do better: somewhere (UIService?) there needs to be an onEvent(ModuleErroredEvent) that somehow displays the exception with stack trace to the user: either raising a dialog window, or logging the stack trace with the LogService.

kephale commented 1 year ago

@ctrueden @gab1one we have a chance to test ModuleErroredEvent in sciview. This bug hit me a few times while working on sciview this past week. How can we catch these events? EventService?

gselzer commented 1 year ago

@kephale you can catch the events with the EventService, yes. See ModuleErroredEventTest for an example. Note that I don't think you need the subscribe call for SciJava Plugins.

ctrueden commented 1 year ago

Yep, the DefaultSciViewService can add an @EventHandler public void onEvent(ModuleErroredEvent evt) method. As long as the @EventHandler annotation is on there, then the SciJava framework will register the service as an event subscriber upon initialization.

ctrueden commented 1 year ago

I dug into this again today, but what I wrote above doesn't make sense to me ("by default, nothing in the framework subscribes to this event, and so module errors are still eaten and invisible"). While it's true that nothing subscribes to the ModuleErroredEvent, the logic from #459 that @gselzer and I developed does log the error via the LogService to stderr if nothing else consumes the event. So we should now be seeing failed module execution exception stack traces appear in the Console window with Fiji 2.14.0. I'll do more testing soon to confirm. For now I leave this issue open, but no more code may be necessary, unless we also want to have a graphical dialog popup with fancy "details" dropdown with the exception...

ctrueden commented 1 year ago

All right, confirmed, #459 does fix this issue. I forced a sciview command to throw a RuntimeException, and then I see it now on both the actual console and the in SciJava graphical console window. :+1: