isPluginEnabled() called off the main thread, causing freezing issues
hafarooki opened this issue · 13 comments
In AsyncPlayerChatEvent, isPluginEnabled() is being called for McMMO which is apparently not thread safe. It causes a deadlock to occur then RIP. I've had 3 freezes from this.
[15:57:43] [Paper Watchdog Thread/ERROR]: ------------------------------
[15:57:43] [Paper Watchdog Thread/ERROR]: app//org.bukkit.plugin.SimplePluginManager.getPlugin(SimplePluginManager.java:361)
[15:57:43] [Paper Watchdog Thread/ERROR]: Current Thread: ForkJoinPool-450-worker-8
[15:57:43] [Paper Watchdog Thread/ERROR]: app//org.bukkit.plugin.SimplePluginManager.isPluginEnabled(SimplePluginManager.java:377)
[15:57:43] [Paper Watchdog Thread/ERROR]: PID: 11649 | Suspended: false | Native: false | State: WAITING
[15:57:43] [Paper Watchdog Thread/ERROR]: github.scarsz.discordsrv.DiscordSRV.processChatMessage(DiscordSRV.java:581)
[15:57:43] [Paper Watchdog Thread/ERROR]: Stack:
[15:57:43] [Paper Watchdog Thread/ERROR]: github.scarsz.discordsrv.listeners.PlayerChatListener.onAsyncPlayerChat(PlayerChatListener.java:31)
[15:57:43] [Paper Watchdog Thread/ERROR]: [email protected]/jdk.internal.misc.Unsafe.park(Native Method)
[15:57:43] [Paper Watchdog Thread/ERROR]: com.destroystokyo.paper.event.executor.asm.generated.GeneratedEventExecutor496.execute(Unknown Source)
[15:57:43] [Paper Watchdog Thread/ERROR]: [email protected]/java.util.concurrent.locks.LockSupport.park(LockSupport.java:194)
[15:57:43] [Paper Watchdog Thread/ERROR]: app//org.bukkit.plugin.EventExecutor$2.execute(EventExecutor.java:70)
[15:57:43] [Paper Watchdog Thread/ERROR]: [email protected]/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1668)
[15:57:43] [Paper Watchdog Thread/ERROR]: app//co.aikar.timings.TimedEventExecutor.execute(TimedEventExecutor.java:74)
[15:57:43] [Paper Watchdog Thread/ERROR]: [email protected]/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:177)
[15:57:43] [Paper Watchdog Thread/ERROR]: app//org.bukkit.plugin.RegisteredListener.callEvent(RegisteredListener.java:62)
[15:57:43] [Paper Watchdog Thread/ERROR]: ------------------------------
One of the many tasks it's being called on, mostly with the same stacktrace.
[15:57:23] [Paper Watchdog Thread/ERROR]: ------------------------------
[15:57:28] [Paper Watchdog Thread/ERROR]: The server has not responded for 5 seconds! Creating thread dump
[15:57:28] [Paper Watchdog Thread/ERROR]: ------------------------------
[15:57:28] [Paper Watchdog Thread/ERROR]: Server thread dump (Look for plugins here before reporting to Paper!):
[15:57:28] [Paper Watchdog Thread/ERROR]: ------------------------------
[15:57:28] [Paper Watchdog Thread/ERROR]: Current Thread: Server thread
[15:57:28] [Paper Watchdog Thread/ERROR]: PID: 21 | Suspended: false | Native: false | State: BLOCKED
[15:57:28] [Paper Watchdog Thread/ERROR]: Stack:
[15:57:28] [Paper Watchdog Thread/ERROR]: app//org.bukkit.plugin.SimplePluginManager.callEvent(SimplePluginManager.java:511)
[15:57:28] [Paper Watchdog Thread/ERROR]: app//net.minecraft.server.v1_12_R1.PlayerConnection.a(PlayerConnection.java:694)
[15:57:28] [Paper Watchdog Thread/ERROR]: app//net.minecraft.server.v1_12_R1.PacketPlayInFlying.a(SourceFile:126)
[15:57:28] [Paper Watchdog Thread/ERROR]: app//net.minecraft.server.v1_12_R1.PacketPlayInFlying$PacketPlayInPositionLook.a(SourceFile:18)
[15:57:28] [Paper Watchdog Thread/ERROR]: app//net.minecraft.server.v1_12_R1.PlayerConnectionUtils.lambda$ensureMainThread$0(PlayerConnectionUtils.java:14)
[15:57:28] [Paper Watchdog Thread/ERROR]: app//net.minecraft.server.v1_12_R1.PlayerConnectionUtils$$Lambda$808/417172150.run(Unknown Source)
[15:57:28] [Paper Watchdog Thread/ERROR]: [email protected]/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:514)
[15:57:28] [Paper Watchdog Thread/ERROR]: [email protected]/java.util.concurrent.FutureTask.run(FutureTask.java:264)
[15:57:28] [Paper Watchdog Thread/ERROR]: app//net.minecraft.server.v1_12_R1.SystemUtils.a(SourceFile:46)
[15:57:28] [Paper Watchdog Thread/ERROR]: app//net.minecraft.server.v1_12_R1.MinecraftServer.D(MinecraftServer.java:849)
[15:57:28] [Paper Watchdog Thread/ERROR]: app//net.minecraft.server.v1_12_R1.DedicatedServer.D(DedicatedServer.java:423)
[15:57:28] [Paper Watchdog Thread/ERROR]: app//net.minecraft.server.v1_12_R1.MinecraftServer.C(MinecraftServer.java:773)
[15:57:28] [Paper Watchdog Thread/ERROR]: app//net.minecraft.server.v1_12_R1.MinecraftServer.run(MinecraftServer.java:665)
[15:57:28] [Paper Watchdog Thread/ERROR]: [email protected]/java.lang.Thread.run(Thread.java:844)
[15:57:28] [Paper Watchdog Thread/ERROR]: ------------------------------
the deadlock on the main thread (it's a synchronized(this) in the code of that class)
How can return plugin != null && this.plugins.contains(plugin) ? plugin.isEnabled() : false; possibly be thread blocking? Does Paper have a special snowflake implementation of this?
See SimplePluginManager#isPluginEnabled(String)
The method calls getPlugin as indicated by the stacktrace, which is a synchronized method.
This is present in upstream (spigot).
I'm not used to how Paper does it's stack traces. I didn't realize the call was hanging above what I mentioned.
Either way, this is the first time I've ever even seen something like this reported, let alone the first time seeing that #getPlugin isn't thread-safe. I don't understand why this call would hang either, it's just getting a value from a map. As far as I'm concerned, this shouldn't take more than a ms in the real world.
return (Plugin)this.lookupNames.get(name.replace(' ', '_'));
@Miclebrick, if you'd like, you can test http://ci.scarsz.me/job/DiscordSRV/232/artifact/target/DiscordSRV-Build-1.16.4-SNAPSHOT-232.jar (42ba974) to see if that fixes it but as I've said I have literally no clue why that method call would be hanging. It isn't really DiscordSRV's fault that it does, either.
@Scarsz your right, in an ideal world your code should be ok, but Bukkit made mistakes in its plugin model when it was created.
We are stuck with it for most part, so you ultimately have to fix it by not calling that method async, which was unnecessary anyways.
Also what do you mean with how Paper does stack traces? that's the normal stack trace printed by Java.
We are stuck with it for most part, so you ultimately have to fix it by not calling that method async, which was unnecessary anyways.
Calling that method sync isn't really possible because it's an exit condition for the entire rest of that method. The build I suggested @Miclebrick try doesn't use this method so maybe that'll work better. I have literally never seen a single report of this method crashing a server when it's called asynchronously, either. This seems like user error more than anything to me.
what do you mean with how Paper does stack traces? that's the normal stack trace printed by Java.
Yes, it is a normal stack trace but it being slightly different threw me off, namely how things were prefixed with app///java.... Don't know, just overlooked it.
That's not paper, something specific to micles environment. (probably kotlin)
I would suggest storing if dependency plugin are enabled to a boolean and change it in plugin enable and disable events
Java 10, not kotlin.
There are also PluginEnable and PluginDisable events if you wish to keep your own separate list in order to support runtime changes to plugins.
Seems like @Miclebrick is aware that his environment is what's specifically causing the issue https://hasteb.in/ukebekar.yaml
Later in that same chat, I said it happened even after I removed that. As you can see in the stacktrace I sent here, it's no longer an issue from my plugin.
In summary, this came down to the Bukkit API being shit in that an event prefixed with Async- is not always asynchronous. Lovely.
In summary, this came down to the Bukkit API being shit in that an event prefixed with Async- is not always asynchronous. Lovely.
Here's the entire javadocs for that class with my own bolding for emphasis.
This event will sometimes fire synchronously, depending on how it was triggered.
The constructor provides a boolean to indicate if the event was fired synchronously or asynchronously. When asynchronous, this event can be called from any thread, sans the main thread, and has limited access to the API.
If a player is the direct cause of this event by an incoming packet, this event will be asynchronous. If a plugin triggers this event by compelling a player to chat, this event will be synchronous.
Care should be taken to check Event.isAsynchronous() and treat the event appropriately.