Thread deadlock on Bukkit
Packsolite opened this issue · 12 comments
Description
Luckperms blocks the main thread causing the server to freeze and crash.
Issues seems to be related to #3483, although it is locking from a different call this time.
Attached a complete stacktrace dump to this issue.
Reproduction Steps
Not quite sure as it is very rare, but does happen every now and then.
Expected Behaviour
To not freeze the main thread.
Server Details
Paperspigot-1.8.9-git-2894af0
LuckPerms Version
5.4.49
Logs and Configs
Extra Details
No response
It looks like you are making queries to a database for this to happen? If so:
In general Player::hasPermission("perm") is safe? Luckperms already modifies the outcome of that.
If you are looking to avoid the bukkit api for whatever reason, you can use User::getCachedData().getPermissionData().checkPermission("perm")? It shouldn't need to perform a DB query every time.
EDIT: After checking the stacktrace it looks to be a bit more complext than that.. somehow the permission data is not being cached correctly?
[21:05:17] [Paper Watchdog Thread/ERROR]: eu.smashmc.smash.game.listener.PlayerToggleSneakListener.toggleSneak(PlayerToggleSneakListener.java:23) whatever this plugin is, it appears to be checking permissions of lots of players whenever they sneak. report this to that plugin instead.
[21:05:17] [Paper Watchdog Thread/ERROR]: eu.smashmc.smash.game.listener.PlayerToggleSneakListener.toggleSneak(PlayerToggleSneakListener.java:23)whatever this plugin is, it appears to be checking permissions of lots of players whenever they sneak. report this to that plugin instead.
This is our plugin, checking a permission once when a player happens to sneak under certain conditions.
// Edit
Actually just checked, it can happen multiple times and can possibly cause a permission check on multiple players, but it has a practical delay of at least 15 seconds.
Should i cache the permission checks? I thought luckperms lookups would be inexpensive...
However, i still think this is a bug as no amount of permission checks should cause luckperms to deadlock...
It looks like you are making queries to a database for this to happen? If so:
In general
Player::hasPermission("perm")is safe? Luckperms already modifies the outcome of that. If you are looking to avoid the bukkit api for whatever reason, you can useUser::getCachedData().getPermissionData().checkPermission("perm")? It shouldn't need to perform a DB query every time.
I am using Player#hasPermission for this. The player is actually comming from a Bukkit.getOnlinePlayers() loop - so the player must be online and should already be cached by luckperms.
I think it would be useful if you would provide the entire log file following up to that crash, and you can choose to censor IPs if you wish to do so. I think also providing the 20-ish lines of code around your permissions check can help make sure there are no issues there.
i highly suspect that "checking permsisions of many players when anyone crouches or uncrouches" has something to do with this problem. sure you have a cooldown, but you iterate over the blocks and check the permission on many players each iteration. there is no context here for how many iterations its doing on
blocks.
blocks is an array with always 9 entries. As said, it checks in worst case two times on a player that is colliding with the wall, which is at max (worst case again) 7 players. It is very, very unlikely that this actually ever happens in a game. (The common case is only one check or even none as a player needs to happen to collide with those blocks if they are placed.)
No matter what, even if there would be hundreds or even thousands of permission checks, in my opinion it would still be a bug if luckperms deadlocks the thread. I don't think the check itself is the issue here...
i assume you are also setting and unsetting this
smash.advantagepermission in your plugin code.
No, i am not.
i highly suspect that "checking permsisions of many players when anyone crouches or uncrouches" has something to do with this problem. sure you have a cooldown, but you iterate over the blocks and check the permission on many players each iteration. there is no context here for how many iterations its doing on blocks. if you have a complex permissions setup with lots of parent groups, it will take longer to calculate permissions. being unable to see more code or details about how your permissions are setup, its hard to tell what the issue actually is.
i assume you are also setting and unsetting this smash.advantage permission in your plugin code. why not just store this advantage data yourself with a map or even on the player directly with bukkit's metadata?
I think it would be useful if you would provide the entire log file following up to that crash, and you can choose to censor IPs if you wish to do so. I think also providing the 20-ish lines of code around your permissions check can help make sure there are no issues there.
Unfortunately i don't have the full log anymore. But i can assure you there was nothing unusual, like no other stack traces, no warnings, no other messages from luckperms.
Here are the lines leading up to the permission call:
PlayerToggleSneakListener.java:
@EventHandler
public void toggleSneak(PlayerToggleSneakEvent event) {
var player = event.getPlayer();
getCharacter(player).onToggleSneak(player, event); // <--- This is the call leading up to the permission check
}
Toph.java:
public void onToggleSneak(Player player, PlayerToggleSneakEvent event) {
if (cooldown.claim(player)) { // 15 seconds cooldown
spawnWall(player, Material.DIRT, Sound.DIG_GRAVEL); // <---
}
}
public void spawnWall(Player player, Material material, Sound sound) {
[...]
pushbackPlayers(player, blocks); // <---
[...]
}
private void pushbackPlayers(Player tophPlayer, List<Block> blocks) {
final float hitboxXZ = 0.6f / 2; // Player hitbox is 0.6 blocks wide
final float hitboxY = 1.8f / 2; // Player hitbox is 1.8 blocks high
for (Block block : blocks) {
final var blockLocation = block.getLocation();
// Assuming all blocks are full blocks
double xMin = blockLocation.getX() - hitboxXZ;
double yMin = blockLocation.getY() - hitboxY;
double zMin = blockLocation.getZ() - hitboxXZ;
double xMax = blockLocation.getX() + hitboxXZ + 1;
double yMax = blockLocation.getY() + hitboxY + 1;
double zMax = blockLocation.getZ() + hitboxXZ + 1;
for (Player other : game.getIngamePlayers()) {
boolean changed = false;
Location pushback = other.getLocation();
while (pushback.getX() > xMin && pushback.getX() < xMax && pushback.getY() > yMin && pushback.getY() < yMax && pushback.getZ() > zMin && pushback.getZ() < zMax) {
pushback.add(other.getLocation()
.subtract(tophPlayer.getLocation())
.toVector()
.setY(0)
.normalize());
changed = true;
}
if (changed) {
other.teleport(pushback);
VelocityHandler.applyRawVelocity(other, other.getLocation() // <---
.subtract(tophPlayer.getLocation())
.toVector()
.setY(0)
.normalize()
.multiply(0.5));
}
}
}
}
VelocityHandler.java
public static void applyRawVelocity(Player player, Vector vector) {
final double multiplier = getEffectiveVelocityMultiplier(player); // <---
Vector vec = new Vector(vector.getX() / multiplier, vector.getY(), vector.getZ() / multiplier);
player.setVelocity(vec);
}
private static double getEffectiveVelocityMultiplier(Player player) {
int points = getVelocityPoints(player);
double multiplier = (double) (points + baseVelocity) / baseVelocity;
/* Do they have the advantage permission? */
if (AdvantageUtil.hasAdvantage(player)) { // <--- This is the call leading up to the permission check
multiplier -= multiplier * AdvantageUtil.VELOCITY_REDUCTION;
}
return multiplier;
}
AdvantageUtil.java:
public static boolean hasAdvantage(Player player) {
return player.hasPermission("smash.advantage");
}
In worst case scenario, the permission check can be called for every online player up to 2 times every 15 seconds, which should not be very much... In a realistic scenario it is only about one to two times every couple of minutes.
have you actually verified that it is actually checking the permission the number of times you claim it should?
Yeah I am not seeing anything obviously wrong here..
I was mostly interested in the logs though as that may have even small warnings at startup or after that would indicate issues with loading permissions for a player. If you are able to reproduce this behavior that would be great.
have you actually verified that it is actually checking the permission the number of times you claim it should?
Yes.
// Edit
I added a debug log whenever the method is called. It is also called from other places and it added up to a total of 56 calls in ~5 minutes. This is definitely more than i originally stated, however i think it should still not be the issue here.
Yeah I am not seeing anything obviously wrong here.. I was mostly interested in the logs though as that may have even small warnings at startup or after that would indicate issues with loading permissions for a player. If you are able to reproduce this behavior that would be great.
Gonna keep an eye open 👀
LuckPerms doesn't actually appear the second time the server thread is dumped:
[21:05:17] [Paper Watchdog Thread/ERROR]: Current Thread: Server thread
[21:05:17] [Paper Watchdog Thread/ERROR]: PID: 39 | Suspended: false | Native: false | State: RUNNABLE
[21:05:17] [Paper Watchdog Thread/ERROR]: Thread is waiting on monitor(s):
[21:05:17] [Paper Watchdog Thread/ERROR]: Locked on:app//org.bukkit.plugin.SimplePluginManager.callEvent(SimplePluginManager.java:475)
[21:05:17] [Paper Watchdog Thread/ERROR]: Stack:
[21:05:17] [Paper Watchdog Thread/ERROR]: [email protected]/java.util.HashMap.hash(HashMap.java:338)
[21:05:17] [Paper Watchdog Thread/ERROR]: [email protected]/java.util.HashMap.getNode(HashMap.java:568)
[21:05:17] [Paper Watchdog Thread/ERROR]: [email protected]/java.util.HashMap.getOrDefault(HashMap.java:1139)
[21:05:17] [Paper Watchdog Thread/ERROR]: eu.smashmc.smash.game.character.CharacterManager.getCharacter(CharacterManager.java:90)
[21:05:17] [Paper Watchdog Thread/ERROR]: eu.smashmc.smash.game.mechanic.VelocityHandler.getEffectiveVelocityMultiplier(VelocityHandler.java:121)
[21:05:17] [Paper Watchdog Thread/ERROR]: eu.smashmc.smash.game.mechanic.VelocityHandler.applyRawVelocity(VelocityHandler.java:99)
[21:05:17] [Paper Watchdog Thread/ERROR]: eu.smashmc.smash.game.character.characters.Toph.pushbackPlayers(Toph.java:163)
[21:05:17] [Paper Watchdog Thread/ERROR]: eu.smashmc.smash.game.character.characters.Toph.spawnWall(Toph.java:110)
[21:05:17] [Paper Watchdog Thread/ERROR]: eu.smashmc.smash.game.character.characters.Toph.onToggleSneak(Toph.java:49)
[21:05:17] [Paper Watchdog Thread/ERROR]: eu.smashmc.smash.game.listener.PlayerToggleSneakListener.toggleSneak(PlayerToggleSneakListener.java:23)
[21:05:17] [Paper Watchdog Thread/ERROR]: jdk.internal.reflect.GeneratedMethodAccessor77.invoke(Unknown Source)
[21:05:17] [Paper Watchdog Thread/ERROR]: [email protected]/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[21:05:17] [Paper Watchdog Thread/ERROR]: [email protected]/java.lang.reflect.Method.invoke(Method.java:568)
[21:05:17] [Paper Watchdog Thread/ERROR]: app//org.bukkit.plugin.java.JavaPluginLoader$1.execute(JavaPluginLoader.java:300)
[21:05:17] [Paper Watchdog Thread/ERROR]: app//co.aikar.timings.TimedEventExecutor.execute(TimedEventExecutor.java:74)
[21:05:17] [Paper Watchdog Thread/ERROR]: app//org.bukkit.plugin.RegisteredListener.callEvent(RegisteredListener.java:62)
[21:05:17] [Paper Watchdog Thread/ERROR]: app//org.bukkit.plugin.SimplePluginManager.fireEvent(SimplePluginManager.java:490)
[21:05:17] [Paper Watchdog Thread/ERROR]: app//org.bukkit.plugin.SimplePluginManager.callEvent(SimplePluginManager.java:475)
[21:05:17] [Paper Watchdog Thread/ERROR]: app//net.minecraft.server.v1_8_R3.PlayerConnection.a(PlayerConnection.java:1344)
[21:05:17] [Paper Watchdog Thread/ERROR]: app//net.minecraft.server.v1_8_R3.PacketPlayInEntityAction.a(SourceFile:43)
[21:05:17] [Paper Watchdog Thread/ERROR]: app//net.minecraft.server.v1_8_R3.PacketPlayInEntityAction.a(SourceFile:9)
[21:05:17] [Paper Watchdog Thread/ERROR]: app//net.minecraft.server.v1_8_R3.PlayerConnectionUtils.lambda$ensureMainThread$0(PlayerConnectionUtils.java:6)
[21:05:17] [Paper Watchdog Thread/ERROR]: app//net.minecraft.server.v1_8_R3.PlayerConnectionUtils$$Lambda$1485/0x00000008017c7208.run(Unknown Source)
[21:05:17] [Paper Watchdog Thread/ERROR]: [email protected]/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
[21:05:17] [Paper Watchdog Thread/ERROR]: [email protected]/java.util.concurrent.FutureTask.run(FutureTask.java:264)
[21:05:17] [Paper Watchdog Thread/ERROR]: app//net.minecraft.server.v1_8_R3.SystemUtils.a(SourceFile:44)
[21:05:17] [Paper Watchdog Thread/ERROR]: app//net.minecraft.server.v1_8_R3.MinecraftServer.B(MinecraftServer.java:781)
[21:05:17] [Paper Watchdog Thread/ERROR]: app//net.minecraft.server.v1_8_R3.DedicatedServer.B(DedicatedServer.java:376)
[21:05:17] [Paper Watchdog Thread/ERROR]: app//net.minecraft.server.v1_8_R3.MinecraftServer.A(MinecraftServer.java:720)
[21:05:17] [Paper Watchdog Thread/ERROR]: app//net.minecraft.server.v1_8_R3.MinecraftServer.run(MinecraftServer.java:613)
[21:05:17] [Paper Watchdog Thread/ERROR]: [email protected]/java.lang.Thread.run(Thread.java:833)
Seems like a coincidence, but please feel free to open another issue if it occurs again.