PluginEvents called out of order.

[ryantheleach]

Expected behavior

I expect to see the events for PluginEnableEvent and PluginDisableEvent reflect the reality of the situation, in that the plugin failed during enablement.

Either the enable event should not be thrown if the event failed to initialize, or the events called in the correct order.

Observed/Actual behavior

[22:29:48 INFO]: [Paper-Test-Plugin-watcher] Loading Paper-Test-Plugin-watcher v1.0.0-SNAPSHOT
[22:29:48 INFO]: [Paper-Test-Plugin-stopper] Loading Paper-Test-Plugin-stopper v1.0.0-SNAPSHOT
[22:29:48 INFO]: Server permissions file permissions.yml is empty, ignoring it
[22:29:48 INFO]: [Paper-Test-Plugin-watcher] Enabling Paper-Test-Plugin-watcher v1.0.0-SNAPSHOT
[22:29:48 INFO]: [Paper-Test-Plugin-watcher] Paper-Test-Plugin-watcher::PluginEnableEvent
[22:29:48 INFO]: [Paper-Test-Plugin-stopper] Enabling Paper-Test-Plugin-stopper v1.0.0-SNAPSHOT
[22:29:48 INFO]: [Paper-Test-Plugin-stopper] Disabling Paper-Test-Plugin-stopper v1.0.0-SNAPSHOT
[22:29:48 INFO]: [Paper-Test-Plugin-watcher] Paper-Test-Plugin-stopper::PluginDisableEvent
[22:29:48 INFO]: [Paper-Test-Plugin-watcher] Paper-Test-Plugin-stopper::PluginEnableEvent
[22:29:48 INFO]: Preparing level "world"
[22:29:49 INFO]: Preparing start region for dimension minecraft:overworld
[22:29:50 INFO]: Time elapsed: 586 ms
[22:29:50 INFO]: Preparing start region for dimension minecraft:the_nether
[22:29:50 INFO]: Time elapsed: 310 ms
[22:29:50 INFO]: Preparing start region for dimension minecraft:the_end
[22:29:51 INFO]: Time elapsed: 566 ms
[22:29:51 INFO]: [Paper-Test-Plugin-watcher] Paper-Test-Plugin-watcher = true
[22:29:51 INFO]: [Paper-Test-Plugin-watcher] Paper-Test-Plugin-stopper = false

Note that enable and disable logging lines are in the correct order, but the event is not.

[22:29:48 INFO]: [Paper-Test-Plugin-stopper] Enabling Paper-Test-Plugin-stopper v1.0.0-SNAPSHOT
[22:29:48 INFO]: [Paper-Test-Plugin-stopper] Disabling Paper-Test-Plugin-stopper v1.0.0-SNAPSHOT

[22:29:48 INFO]: [Paper-Test-Plugin-watcher] Paper-Test-Plugin-stopper::PluginDisableEvent
[22:29:48 INFO]: [Paper-Test-Plugin-watcher] Paper-Test-Plugin-stopper::PluginEnableEvent

Note that the status of the stopper is correctly disabled at server load time.

[22:29:51 INFO]: [Paper-Test-Plugin-watcher] Paper-Test-Plugin-watcher = true
[22:29:51 INFO]: [Paper-Test-Plugin-watcher] Paper-Test-Plugin-stopper = false

Steps/models to reproduce

Watcher: (Note: Stopper should probably depend on Watcher)

package io.papermc.paper.testplugin;

import org.bukkit.event.EventHandler;
import org.bukkit.event.EventPriority;
import org.bukkit.event.Listener;
import org.bukkit.event.server.PluginDisableEvent;
import org.bukkit.event.server.PluginEnableEvent;
import org.bukkit.event.server.PluginEvent;
import org.bukkit.event.server.ServerLoadEvent;
import org.bukkit.plugin.java.JavaPlugin;

import java.util.Arrays;
import java.util.logging.Level;

public final class TestPluginWatcher extends JavaPlugin implements Listener {
    @Override
    public void onEnable() {
        this.getServer().getPluginManager().registerEvents(this, this);
    }

    @EventHandler(priority = EventPriority.MONITOR, ignoreCancelled = false)
    private void onPluginEnableEvent(final PluginEnableEvent e) {
        this.onPluginEvent(e);
    }

    @EventHandler(priority = EventPriority.MONITOR, ignoreCancelled = false)
    private void onPluginDisableEvent(final PluginDisableEvent e) {
        this.onPluginEvent(e);
    }

    private void onPluginEvent(final PluginEvent e) {
        this.getLogger().log(Level.INFO, e.getPlugin().getName()+"::"+e.getEventName());
    }

    @EventHandler(priority = EventPriority.MONITOR, ignoreCancelled = false)
    private void onReady(ServerLoadEvent e) {
        Arrays.stream(this.getServer().getPluginManager().getPlugins())
            .map(p -> p.getName()+" = "+this.getServer().getPluginManager().isPluginEnabled(p))
            .forEach(s -> this.getLogger().log(Level.INFO, s));
    }
}

Stopper:

package io.papermc.paper.testplugin;

import org.bukkit.event.EventHandler;
import org.bukkit.event.EventPriority;
import org.bukkit.event.Listener;
import org.bukkit.plugin.java.JavaPlugin;

import java.util.Arrays;
import java.util.logging.Level;

public final class TestPluginStopper extends JavaPlugin implements Listener {
    @Override
    public void onEnable() {
        this.getServer().getPluginManager().disablePlugin(this);
    }

Plugin and Datapack List

Just the 2 listed above.

Paper version

Latest, at time of writing:

[22:37:31 INFO]: This server is running Paper version null (MC: 1.18.1) (Implementing API version 1.18.1-R0.1-SNAPSHOT) (Git: null on null)
Unknown version, custom build?

Other

No response

[ryantheleach]

Throwing results in the following log:

[22:43:47 INFO]: [Paper-Test-Plugin-thrower] Enabling Paper-Test-Plugin-thrower v1.0.0-SNAPSHOT
[22:43:47 ERROR]: Error occurred while enabling Paper-Test-Plugin-thrower v1.0.0-SNAPSHOT (Is it up to date?)
java.lang.RuntimeException: Succeeded to fail
    at io.papermc.paper.testplugin.TestPluginThrower.onEnable(TestPluginThrower.java:18) ~[test-plugin-1.0.0-SNAPSHOT.jar:?]
    at org.bukkit.plugin.java.JavaPlugin.setEnabled(JavaPlugin.java:264) ~[paper-api-1.18.1-R0.1-SNAPSHOT.jar:?]
    at org.bukkit.plugin.java.JavaPluginLoader.enablePlugin(JavaPluginLoader.java:370) ~[paper-api-1.18.1-R0.1-SNAPSHOT.jar:?]
    at org.bukkit.plugin.SimplePluginManager.enablePlugin(SimplePluginManager.java:500) ~[paper-api-1.18.1-R0.1-SNAPSHOT.jar:?]
    at org.bukkit.craftbukkit.CraftServer.enablePlugin(CraftServer.java:564) ~[main/:?]
    at org.bukkit.craftbukkit.CraftServer.enablePlugins(CraftServer.java:478) ~[main/:?]
    at net.minecraft.server.dedicated.DedicatedServer.initServer(DedicatedServer.java:286) ~[main/:?]
    at net.minecraft.server.MinecraftServer.runServer(MinecraftServer.java:1202) ~[main/:?]
    at net.minecraft.server.MinecraftServer.lambda$spin$0(MinecraftServer.java:317) ~[main/:?]
    at java.lang.Thread.run(Thread.java:833) ~[?:?]
[22:43:47 INFO]: [Paper-Test-Plugin-thrower] Disabling Paper-Test-Plugin-thrower v1.0.0-SNAPSHOT
[22:43:47 INFO]: [Paper-Test-Plugin-watcher] Paper-Test-Plugin-thrower::PluginDisableEvent
[22:43:47 INFO]: [Paper-Test-Plugin-stopper] Enabling Paper-Test-Plugin-stopper v1.0.0-SNAPSHOT
[22:43:47 INFO]: [Paper-Test-Plugin-stopper] Disabling Paper-Test-Plugin-stopper v1.0.0-SNAPSHOT
[22:43:47 INFO]: [Paper-Test-Plugin-watcher] Paper-Test-Plugin-stopper::PluginDisableEvent
[22:43:47 INFO]: [Paper-Test-Plugin-watcher] Paper-Test-Plugin-stopper::PluginEnableEvent

Results in a PluginDisableEvent without a corresponding Enable event.

This violates the principal of least surprise, but I could understand that being intentional if documented.

[electronicboy]

Well, this is likely derived from upstream behavior; I guess we could not call the enable event if the plugin disables and the disable event if the enable hasn't fired, but that creates a good chunk of eer here, but, I don't think that there is a great solution here which doesn't potentially introduce some risks, so am not sure how strong the argument here is to break from upstream

[ryantheleach]

I havn't tested upstream yet, it may be better PR'd to them.

[Sxtanna]

This violates the principal of least surprise, but I could understand that being intentional if documented.

Not to say this behavior shouldn't probably be looked at, but this does not violate the principle of least surprise.