Could not pass event AsyncPlayerChatEvent to PwnFilter
mibby opened this issue · 35 comments
PwnFilter dev 104
[13:06:51] [Async Chat Thread - #106/ERROR]: Could not pass event AsyncPlayerChatEvent to PwnFilter v3.9.1-SNAPSHOT-b104
java.lang.NullPointerException
at com.pwn9.filter.bukkit.listener.PwnFilterPlayerListener.onPlayerChat(PwnFilterPlayerListener.java:66) ~[?:?]
at com.pwn9.filter.bukkit.listener.PwnFilterPlayerListener.lambda$activate$32(PwnFilterPlayerListener.java:130) ~[?:?]
at co.aikar.timings.TimedEventExecutor.execute(TimedEventExecutor.java:74) ~[patched_1.9.2.jar:git-Paper-3591fb7]
at org.bukkit.plugin.RegisteredListener.callEvent(RegisteredListener.java:62) ~[patched_1.9.2.jar:git-Paper-3591fb7]
at org.bukkit.plugin.SimplePluginManager.fireEvent(SimplePluginManager.java:517) [patched_1.9.2.jar:git-Paper-3591fb7]
at org.bukkit.plugin.SimplePluginManager.callEvent(SimplePluginManager.java:499) [patched_1.9.2.jar:git-Paper-3591fb7]
at net.minecraft.server.v1_9_R1.PlayerConnection.chat(PlayerConnection.java:1303) [patched_1.9.2.jar:git-Paper-3591fb7]
at net.minecraft.server.v1_9_R1.PlayerConnection.a(PlayerConnection.java:1218) [patched_1.9.2.jar:git-Paper-3591fb7]
at net.minecraft.server.v1_9_R1.PacketPlayInChat$1.run(PacketPlayInChat.java:39) [patched_1.9.2.jar:git-Paper-3591fb7]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_92]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_92]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:1.8.0_92]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:1.8.0_92]
at java.lang.Thread.run(Thread.java:745) [?:1.8.0_92]
[13:06:51] [Server thread/ERROR]: Could not pass event PlayerCommandPreprocessEvent to PwnFilter v3.9.1-SNAPSHOT-b104
java.lang.NullPointerException
at com.pwn9.filter.bukkit.listener.PwnFilterCommandListener.eventProcessor(PwnFilterCommandListener.java:98) ~[?:?]
at com.pwn9.filter.bukkit.listener.PwnFilterCommandListener.lambda$activate$39(PwnFilterCommandListener.java:65) ~[?:?]
at co.aikar.timings.TimedEventExecutor.execute(TimedEventExecutor.java:74) ~[patched_1.9.2.jar:git-Paper-3591fb7]
at org.bukkit.plugin.RegisteredListener.callEvent(RegisteredListener.java:62) ~[patched_1.9.2.jar:git-Paper-3591fb7]
at org.bukkit.plugin.SimplePluginManager.fireEvent(SimplePluginManager.java:517) [patched_1.9.2.jar:git-Paper-3591fb7]
at org.bukkit.plugin.SimplePluginManager.callEvent(SimplePluginManager.java:502) [patched_1.9.2.jar:git-Paper-3591fb7]
at net.minecraft.server.v1_9_R1.PlayerConnection.handleCommand(PlayerConnection.java:1380) [patched_1.9.2.jar:git-Paper-3591fb7]
at net.minecraft.server.v1_9_R1.PlayerConnection.a(PlayerConnection.java:1193) [patched_1.9.2.jar:git-Paper-3591fb7]
at net.minecraft.server.v1_9_R1.PacketPlayInChat.a(PacketPlayInChat.java:45) [patched_1.9.2.jar:git-Paper-3591fb7]
at net.minecraft.server.v1_9_R1.PacketPlayInChat.a(PacketPlayInChat.java:5) [patched_1.9.2.jar:git-Paper-3591fb7]
at net.minecraft.server.v1_9_R1.PlayerConnectionUtils$1.run(SourceFile:13) [patched_1.9.2.jar:git-Paper-3591fb7]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_92]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_92]
at net.minecraft.server.v1_9_R1.SystemUtils.a(SourceFile:45) [patched_1.9.2.jar:git-Paper-3591fb7]
at net.minecraft.server.v1_9_R1.MinecraftServer.D(MinecraftServer.java:811) [patched_1.9.2.jar:git-Paper-3591fb7]
at net.minecraft.server.v1_9_R1.DedicatedServer.D(DedicatedServer.java:404) [patched_1.9.2.jar:git-Paper-3591fb7]
at net.minecraft.server.v1_9_R1.MinecraftServer.C(MinecraftServer.java:721) [patched_1.9.2.jar:git-Paper-3591fb7]
at net.minecraft.server.v1_9_R1.MinecraftServer.run(MinecraftServer.java:620) [patched_1.9.2.jar:git-Paper-3591fb7]
at java.lang.Thread.run(Thread.java:745) [?:1.8.0_92]
Not that I am aware of, unless the plugin routinely reloads itself internally. The error seems to be spontaneous. A few seconds before the error occurred, someone used the command /spawn.
[20:48:52] [Async Chat Thread - #43/ERROR]: Could not pass event AsyncPlayerChatEvent to PwnFilter v3.9.1-SNAPSHOT-b104
java.lang.NullPointerException
at com.pwn9.filter.bukkit.listener.PwnFilterPlayerListener.onPlayerChat(PwnFilterPlayerListener.java:66) ~[?:?]
at com.pwn9.filter.bukkit.listener.PwnFilterPlayerListener.lambda$activate$32(PwnFilterPlayerListener.java:130) ~[?:?]
at co.aikar.timings.TimedEventExecutor.execute(TimedEventExecutor.java:74) ~[patched_1.9.2.jar:git-Paper-3591fb7]
at org.bukkit.plugin.RegisteredListener.callEvent(RegisteredListener.java:62) ~[patched_1.9.2.jar:git-Paper-3591fb7]
at org.bukkit.plugin.SimplePluginManager.fireEvent(SimplePluginManager.java:517) [patched_1.9.2.jar:git-Paper-3591fb7]
at org.bukkit.plugin.SimplePluginManager.callEvent(SimplePluginManager.java:499) [patched_1.9.2.jar:git-Paper-3591fb7]
at net.minecraft.server.v1_9_R1.PlayerConnection.chat(PlayerConnection.java:1303) [patched_1.9.2.jar:git-Paper-3591fb7]
at net.minecraft.server.v1_9_R1.PlayerConnection.a(PlayerConnection.java:1218) [patched_1.9.2.jar:git-Paper-3591fb7]
at net.minecraft.server.v1_9_R1.PacketPlayInChat$1.run(PacketPlayInChat.java:39) [patched_1.9.2.jar:git-Paper-3591fb7]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_92]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_92]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:1.8.0_92]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:1.8.0_92]
at java.lang.Thread.run(Thread.java:745) [?:1.8.0_92]
[20:48:52] [Server thread/ERROR]: Could not pass event PlayerCommandPreprocessEvent to PwnFilter v3.9.1-SNAPSHOT-b104
java.lang.NullPointerException
at com.pwn9.filter.bukkit.listener.PwnFilterCommandListener.eventProcessor(PwnFilterCommandListener.java:98) ~[?:?]
at com.pwn9.filter.bukkit.listener.PwnFilterCommandListener.lambda$activate$39(PwnFilterCommandListener.java:65) ~[?:?]
at co.aikar.timings.TimedEventExecutor.execute(TimedEventExecutor.java:78) ~[patched_1.9.2.jar:git-Paper-3591fb7]
at org.bukkit.plugin.RegisteredListener.callEvent(RegisteredListener.java:62) ~[patched_1.9.2.jar:git-Paper-3591fb7]
at org.bukkit.plugin.SimplePluginManager.fireEvent(SimplePluginManager.java:517) [patched_1.9.2.jar:git-Paper-3591fb7]
at org.bukkit.plugin.SimplePluginManager.callEvent(SimplePluginManager.java:502) [patched_1.9.2.jar:git-Paper-3591fb7]
at net.minecraft.server.v1_9_R1.PlayerConnection.handleCommand(PlayerConnection.java:1380) [patched_1.9.2.jar:git-Paper-3591fb7]
at net.minecraft.server.v1_9_R1.PlayerConnection.a(PlayerConnection.java:1193) [patched_1.9.2.jar:git-Paper-3591fb7]
at net.minecraft.server.v1_9_R1.PacketPlayInChat.a(PacketPlayInChat.java:45) [patched_1.9.2.jar:git-Paper-3591fb7]
at net.minecraft.server.v1_9_R1.PacketPlayInChat.a(PacketPlayInChat.java:5) [patched_1.9.2.jar:git-Paper-3591fb7]
at net.minecraft.server.v1_9_R1.PlayerConnectionUtils$1.run(SourceFile:13) [patched_1.9.2.jar:git-Paper-3591fb7]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_92]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_92]
at net.minecraft.server.v1_9_R1.SystemUtils.a(SourceFile:45) [patched_1.9.2.jar:git-Paper-3591fb7]
at net.minecraft.server.v1_9_R1.MinecraftServer.D(MinecraftServer.java:811) [patched_1.9.2.jar:git-Paper-3591fb7]
at net.minecraft.server.v1_9_R1.DedicatedServer.D(DedicatedServer.java:404) [patched_1.9.2.jar:git-Paper-3591fb7]
at net.minecraft.server.v1_9_R1.MinecraftServer.C(MinecraftServer.java:721) [patched_1.9.2.jar:git-Paper-3591fb7]
at net.minecraft.server.v1_9_R1.MinecraftServer.run(MinecraftServer.java:620) [patched_1.9.2.jar:git-Paper-3591fb7]
at java.lang.Thread.run(Thread.java:745) [?:1.8.0_92]
I will fix this NPE, but I'm confused why this is happening. I'm looking up players using the getOfflinePlayer(uuid) call, which should always match a player that has been on the server. I don't understand how player chat events are coming from players that have never been online?
This is vexing. I have made some changes which should protect against the NPE. (But the filter will not run on that message). Additionally, you will get INFO level messages when this happens again. If you can attach them to this issue, it will help me debug this further. PwnFilter Build 105
At the moment, I can't figure out why the filter can't find a player that has just sent a message. It makes no sense, but I'm sure I'll facepalm when I figure it out.
Find any entries in your logs, yet? They should be multi-line, and start with:
[INFO] Filtering Aborted. Unable to lookup player in Chat Event.
@ptoal Going through my logs since the 26th, occurred 20 times. Most of them related to people connecting through minechat on their phone, but not all of them.
[16:00:00] [Async Chat Thread - #14/INFO]: [PwnFilter] Filtering Aborted. Unable to lookup player in Chat Event. PlayerUUID: 91fc96bb-b5f9-4d2d-9d95-c9c5632c46a7
[16:00:00] [Async Chat Thread - #14/INFO]: [PwnFilter] Message: Oh there
[16:00:00] [Async Chat Thread - #14/INFO]: [PwnFilter] AuthorServices: []
[16:00:00] [Async Chat Thread - #14/INFO]: [PwnFilter] Bukkit player online: true
[15:42:24] [Async Chat Thread - #139/INFO]: [PwnFilter] Filtering Aborted. Unable to lookup player in Chat Event. PlayerUUID: ef671e91-6f8c-4ad3-bbf0-e55a452d18e4
[15:42:24] [Async Chat Thread - #139/INFO]: [PwnFilter] Message: connected with an Android device using MineChat
[15:42:24] [Async Chat Thread - #139/INFO]: [PwnFilter] AuthorServices: [com.pwn9.filter.bukkit.BukkitAPI@36c0bcf2]
[15:42:24] [Async Chat Thread - #139/INFO]: [PwnFilter] Bukkit player online: true
[01:18:36] [Async Chat Thread - #69/INFO]: [PwnFilter] Filtering Aborted. Unable to lookup player in Chat Event. PlayerUUID: 24e85fc2-876b-46f6-bfa7-63e1b40bcaf2
[01:18:36] [Async Chat Thread - #69/INFO]: [PwnFilter] Message: connected with an iPhone using MineChat
[01:18:36] [Async Chat Thread - #69/INFO]: [PwnFilter] AuthorServices: [com.pwn9.filter.bukkit.BukkitAPI@60ce33b2]
[01:18:36] [Async Chat Thread - #69/INFO]: [PwnFilter] Bukkit player online: true
[23:03:40] [Async Chat Thread - #51/INFO]: [PwnFilter] Filtering Aborted. Unable to lookup player in Chat Event. PlayerUUID: cbbb484d-30b6-4f4b-9644-bc5cf37d8317
[23:03:40] [Async Chat Thread - #51/INFO]: [PwnFilter] Message: why am i an idiot
[23:03:40] [Async Chat Thread - #51/INFO]: [PwnFilter] AuthorServices: [com.pwn9.filter.bukkit.BukkitAPI@732d280c]
[23:03:40] [Async Chat Thread - #51/INFO]: [PwnFilter] Bukkit player online: true
Well, that first one is interesting. Somehow there's a service not registered that should be, or maybe there's a concurrency problem. The other ones don't make any sense, though, since the player is still online, and the lookup service seems to exist. The MineChat messages are usually sent right after logon. I wonder if there's some temporary failure during lookup when players connect.
If there are any other events that seem to be related, and you can help narrow down when this is happening, it would be helpful. In the mean time, I'll continue doing static analysis of the code, to see if I can figure out what's going on.
Looking through logs as of the last 24 hours, it is just more of the same. Players using minechat and someone who was chatting normally in-game. Perhaps add more debug output to the filter aborting to figure out why it can't lookup the online player?
[00:43:27] [Async Chat Thread - #66/INFO]: [PwnFilter] Filtering Aborted. Unable to lookup player in Chat Event. PlayerUUID: 24e85fc2-876b-46f6-bfa7-63e1b40bcaf2
[00:43:27] [Async Chat Thread - #66/INFO]: [PwnFilter] Message: connected with an iPhone using MineChat
[00:43:27] [Async Chat Thread - #66/INFO]: [PwnFilter] AuthorServices: [com.pwn9.filter.bukkit.BukkitAPI@60ce33b2]
[00:43:27] [Async Chat Thread - #66/INFO]: [PwnFilter] Bukkit player online: true
[01:18:36] [Async Chat Thread - #69/INFO]: [PwnFilter] Filtering Aborted. Unable to lookup player in Chat Event. PlayerUUID: 24e85fc2-876b-46f6-bfa7-63e1b40bcaf2
[01:18:36] [Async Chat Thread - #69/INFO]: [PwnFilter] Message: connected with an iPhone using MineChat
[01:18:36] [Async Chat Thread - #69/INFO]: [PwnFilter] AuthorServices: [com.pwn9.filter.bukkit.BukkitAPI@60ce33b2]
[01:18:36] [Async Chat Thread - #69/INFO]: [PwnFilter] Bukkit player online: true
[15:42:24] [Async Chat Thread - #139/INFO]: [PwnFilter] Filtering Aborted. Unable to lookup player in Chat Event. PlayerUUID: ef671e91-6f8c-4ad3-bbf0-e55a452d18e4
[15:42:24] [Async Chat Thread - #139/INFO]: [PwnFilter] Message: connected with an Android device using MineChat
[15:42:24] [Async Chat Thread - #139/INFO]: [PwnFilter] AuthorServices: [com.pwn9.filter.bukkit.BukkitAPI@36c0bcf2]
[15:42:24] [Async Chat Thread - #139/INFO]: [PwnFilter] Bukkit player online: true
[19:18:10] [Async Chat Thread - #30/INFO]: [PwnFilter] Filtering Aborted. Unable to lookup player in Chat Event. PlayerUUID: 24e85fc2-876b-46f6-bfa7-63e1b40bcaf2
[19:18:10] [Async Chat Thread - #30/INFO]: [PwnFilter] Message: connected with an iPhone using MineChat
[19:18:10] [Async Chat Thread - #30/INFO]: [PwnFilter] AuthorServices: [com.pwn9.filter.bukkit.BukkitAPI@3ee42135]
[19:18:10] [Async Chat Thread - #30/INFO]: [PwnFilter] Bukkit player online: true
[11:28:40] [Async Chat Thread - #78/INFO]: [PwnFilter] Filtering Aborted. Unable to lookup player in Chat Event. PlayerUUID: ef671e91-6f8c-4ad3-bbf0-e55a452d18e4
[11:28:40] [Async Chat Thread - #78/INFO]: [PwnFilter] Message: connected with an Android device using MineChat
[11:28:40] [Async Chat Thread - #78/INFO]: [PwnFilter] AuthorServices: [com.pwn9.filter.bukkit.BukkitAPI@3d7097c4]
[11:28:40] [Async Chat Thread - #78/INFO]: [PwnFilter] Bukkit player online: true
[12:23:35] [Async Chat Thread - #90/INFO]: [PwnFilter] Filtering Aborted. Unable to lookup player in Chat Event. PlayerUUID: 757f3dd7-8a57-432b-8a7c-e1d071843bc9
[12:23:35] [Async Chat Thread - #90/INFO]: [PwnFilter] Message: Welcome back.
[12:23:35] [Async Chat Thread - #90/INFO]: [PwnFilter] AuthorServices: [com.pwn9.filter.bukkit.BukkitAPI@3d7097c4]
[12:23:35] [Async Chat Thread - #90/INFO]: [PwnFilter] Bukkit player online: true
[15:39:46] [Async Chat Thread - #126/INFO]: [PwnFilter] Filtering Aborted. Unable to lookup player in Chat Event. PlayerUUID: ef671e91-6f8c-4ad3-bbf0-e55a452d18e4
[15:39:46] [Async Chat Thread - #126/INFO]: [PwnFilter] Message: connected with an Android device using MineChat
[15:39:46] [Async Chat Thread - #126/INFO]: [PwnFilter] AuthorServices: [com.pwn9.filter.bukkit.BukkitAPI@3d7097c4]
[15:39:46] [Async Chat Thread - #126/INFO]: [PwnFilter] Bukkit player online: true
[16:30:55] [Async Chat Thread - #6/INFO]: [PwnFilter] Filtering Aborted. Unable to lookup player in Chat Event. PlayerUUID: 24e85fc2-876b-46f6-bfa7-63e1b40bcaf2
[16:30:55] [Async Chat Thread - #6/INFO]: [PwnFilter] Message: connected with an iPhone using MineChat
[16:30:55] [Async Chat Thread - #6/INFO]: [PwnFilter] AuthorServices: [com.pwn9.filter.bukkit.BukkitAPI@23228e9f]
[16:30:55] [Async Chat Thread - #6/INFO]: [PwnFilter] Bukkit player online: true
Ok. Got my build server sorted out for now. (long story). Give 112 a try, it has a bit more info when the Bukkit API times out. I'm wondering if the server is busy when I'm making the call, or there's some sort of asynchronous thing happening.
@ptoal Nothing really new. Just states the call timed out. When a user connects with minechat, the app forces them to run /spawn, then broadcasts that they are using the chat client. Could consecutive commands have something to do with it?
Full log of player when error occurs.
[10:58:46] [User Authenticator #81/INFO]: UUID of player <player> is <uuid>
[10:58:46] [Server thread/INFO]: <player>[IP:PORT] logged in with entity id 541237 at ([world]-27349.5, 63.0, -2443.5)
[10:58:46] [Server thread/INFO]: [+] <player> has joined the server.
[10:58:51] [Server thread/INFO]: <player> issued server command: /spawn
[10:58:53] [Async Chat Thread - #71/WARN]: [PwnFilter] Bukkit API call timed out (>3s).
[10:58:53] [Async Chat Thread - #71/INFO]: [PwnFilter] Filtering Aborted. Unable to lookup player in Chat Event. PlayerUUID: ef671e91-6f8c-4ad3-bbf0-e55a452d18e4
[10:58:53] [Async Chat Thread - #71/INFO]: [PwnFilter] Message: connected with an Android device using MineChat
[10:58:53] [Async Chat Thread - #71/INFO]: [PwnFilter] AuthorServices: [com.pwn9.filter.bukkit.BukkitAPI@b00ffa6]
[10:58:53] [Async Chat Thread - #71/INFO]: [PwnFilter] Bukkit player online: true
[10:58:53] [Async Chat Thread - #71/INFO]: <player>: connected with an Android device using MineChat
More PwnFilter warnings only.
[02:58:17] [Async Chat Thread - #65/WARN]: [PwnFilter] Bukkit API call timed out (>3s).
[02:58:17] [Async Chat Thread - #65/INFO]: [PwnFilter] Filtering Aborted. Unable to lookup player in Chat Event. PlayerUUID: 24e85fc2-876b-46f6-bfa7-63e1b40bcaf2
[02:58:17] [Async Chat Thread - #65/INFO]: [PwnFilter] Message: connected with an iPhone using MineChat
[02:58:17] [Async Chat Thread - #65/INFO]: [PwnFilter] AuthorServices: [com.pwn9.filter.bukkit.BukkitAPI@3364570c]
[02:58:17] [Async Chat Thread - #65/INFO]: [PwnFilter] Bukkit player online: true
[10:58:53] [Async Chat Thread - #71/WARN]: [PwnFilter] Bukkit API call timed out (>3s).
[10:58:53] [Async Chat Thread - #71/INFO]: [PwnFilter] Filtering Aborted. Unable to lookup player in Chat Event. PlayerUUID: ef671e91-6f8c-4ad3-bbf0-e55a452d18e4
[10:58:53] [Async Chat Thread - #71/INFO]: [PwnFilter] Message: connected with an Android device using MineChat
[10:58:53] [Async Chat Thread - #71/INFO]: [PwnFilter] AuthorServices: [com.pwn9.filter.bukkit.BukkitAPI@b00ffa6]
[10:58:53] [Async Chat Thread - #71/INFO]: [PwnFilter] Bukkit player online: true
[21:53:16] [Async Chat Thread - #79/WARN]: [PwnFilter] Bukkit API call timed out (>3s).
[21:53:16] [Async Chat Thread - #79/INFO]: [PwnFilter] Filtering Aborted. Unable to lookup player in Chat Event. PlayerUUID: 91fc96bb-b5f9-4d2d-9d95-c9c5632c46a7
[21:53:16] [Async Chat Thread - #79/INFO]: [PwnFilter] Message: connected with an iPhone using MineChat
[21:53:16] [Async Chat Thread - #79/INFO]: [PwnFilter] AuthorServices: [com.pwn9.filter.bukkit.BukkitAPI@45cb9afe]
[21:53:16] [Async Chat Thread - #79/INFO]: [PwnFilter] Bukkit player online: true
Just for reference, this issue is new. I never noticed it prior to the new commits when development started back up again. So it has to be something you changed?
Actually, that API call time out is significant. In the old version of PwnFilter, I had this really inefficient data cache that would ask the server for all kinds of data every second. With lots of players, or really complex setups this could slow the server down.
Now, the filter doesn't cache the information for every player all the time. It only asks for it on-demand, and then caches it for a short period (about long enough for the filter to run).
What's happening on your server is that the filter is making a call to Bukkit asking it for player information and that call is taking longer than 3 seconds to come back. 3s is a long time. Does your server suffer from lag spikes, where everything just freezes for 3s or more?
Build 116 increases the timeout to 10s. Can you give this one a whirl? If it still times out after 10s, then there is either a major blocking operation happening on your server, or there's something really wrong with my code, or the Bukkit API. :)
Thanks. I really want to figure this one out.
Because Chat events are Asynchronous, and the Bukkit API is not async-safe, the chat listener sends a Callable Task into the main Bukkit thread. For a reason I don't understand, this task (which is just making a single call to getOfflinePlayer(uuid)) is taking longer than 3 seconds to complete on your server.
I'm thinking about removing this call completely as it was something I was going to use in the future, but don't really need right now, and it seems to be causing a problem for you. I don't understand why it is timing out, but if it's still a problem for you in #116, I'll just remove it completely for now.
My server does not suffer from lag spikes as far as I know. I'll update to build 116 and run a profiler/timings log if it still occurs.
Yeah, to filter commands such as /me and private messages. These are the basic filtering options I use.
# Set to 'true' to strip color codes from chat.
# Players with pwnfilter.color or pwnfilter.bypass permissions will still be
# able to use colors.
decolor: false
# The following options enable / disable filtering features
# The 'chat' filter is always enabled.
# Filter text applied to signs
signfilter: false
# Activate item filter (Naming items with Anvil)
itemfilter: false
# Console Filter -- Filter commands entered on console (EXPERIMENTAL)
consolefilter: false
# Filter commands as well as chat true/false
commandfilter: true
# Filter Book Titles and Pages
bookfilter: false
# The "spamfilter" will enable/disable a basic filter that
# prevents a player from entering the same line 2x in a row.
# For chat messages
spamfilter: false
# For /commands
commandspamfilter: false
Unfortunately it is still happening with build #116 - but seems to just be minechat app users, though not everyone who uses it.
[10:01:23] [User Authenticator #39/INFO]: UUID of player <player> is 24e85fc2-876b-46f6-bfa7-63e1b40bcaf2
[10:01:23] [Server thread/INFO]: <player> [/IP:PORT] logged in with entity id 274990 at ([world]-1137.6543397115438, 101.49313574198204, -1824.0945468052323)
[10:01:23] [Server thread/INFO]: [+] <player> has joined the server.
[10:01:25] [Server thread/INFO]: <player> issued server command: /spawn
[10:01:35] [Async Chat Thread - #57/WARN]: [PwnFilter] Bukkit API call timed out (Waited >10s!). Is the server busy?
[10:01:35] [Async Chat Thread - #57/INFO]: [PwnFilter] Filtering Aborted. Unable to lookup player in Chat Event. PlayerUUID: 24e85fc2-876b-46f6-bfa7-63e1b40bcaf2
[10:01:35] [Async Chat Thread - #57/INFO]: [PwnFilter] Message: connected with an iPhone using MineChat
[10:01:35] [Async Chat Thread - #57/INFO]: [PwnFilter] AuthorServices: [com.pwn9.filter.bukkit.BukkitAPI@1b9660b1]
[10:01:35] [Async Chat Thread - #57/INFO]: [PwnFilter] Bukkit player online: true
[10:01:35] [Async Chat Thread - #57/INFO]: <player>: connected with an iPhone using MineChat
[11:56:22] [User Authenticator #65/INFO]: UUID of player <player> is ef671e91-6f8c-4ad3-bbf0-e55a452d18e4
[11:56:22] [Server thread/INFO]: <player>[/IP:PORT] logged in with entity id 497213 at ([world]-27355.5, 63.0, -2443.5)
[11:56:22] [Server thread/INFO]: [+] <player> has joined the server.
[11:56:45] [Server thread/INFO]: <player> issued server command: /spawn
[11:56:55] [Async Chat Thread - #74/WARN]: [PwnFilter] Bukkit API call timed out (Waited >10s!). Is the server busy?
[11:56:55] [Async Chat Thread - #74/INFO]: [PwnFilter] Filtering Aborted. Unable to lookup player in Chat Event. PlayerUUID: ef671e91-6f8c-4ad3-bbf0-e55a452d18e4
[11:56:55] [Async Chat Thread - #74/INFO]: [PwnFilter] Message: connected with an Android device using MineChat
[11:56:55] [Async Chat Thread - #74/INFO]: [PwnFilter] AuthorServices: [com.pwn9.filter.bukkit.BukkitAPI@1b9660b1]
[11:56:55] [Async Chat Thread - #74/INFO]: [PwnFilter] Bukkit player online: true
[11:56:55] [Async Chat Thread - #74/INFO]: <player>: connected with an Android device using MineChat
Oh... I may have an idea what's happening here... Do you have commandfilter enabled, too?
Well, this one is stumping me, as well as the folks in #spigot that I asked for help. It just doesn't make sense that this is happening.
I have added a ton of debugging output to the Bukkit calls. It should throw up all over your server log if this happens again. :)
EDIT: Build 118 (don't use 117!) has these changes. Please let me know what you see.
@ptoal Apologies for the late reply. Been busy.
Here is the debug information you requested on build 118. Again with minechat app users and non-minechat app users.
[10:07:58] [Server thread/INFO]: <player>[/IP:PORT] logged in with entity id 168334 at ([world]23649.83298218544, 82.0625, -5358.896792674761)
[10:07:58] [Server thread/INFO]: [+] <player> has joined the server.
[10:08:00] [Server thread/INFO]: <player> issued server command: /spawn
[10:08:03] [Async Chat Thread - #54/WARN]: [PwnFilter] Bukkit API call timed out (Waited >10s!). Is the server busy?
[10:08:03] [Async Chat Thread - #54/WARN]: [PwnFilter] Task Cancelled?: false Task Done?: false
[10:08:03] [Async Chat Thread - #54/WARN]: [PwnFilter] Cache Load for Player: ee4ed84d-3dee-4f6e-9f90-a0bc6da44dcf
Bukkit Callable executing lookup for: ee4ed84d-3dee-4f6e-9f90-a0bc6da44dcf
Bukkit Callable finished. Player: CraftPlayer{name=NiceTeddyBear}
Looking for author: 55ba06d1-2f32-4b55-995d-2b43af4c8af1
Cache Load for Player: 55ba06d1-2f32-4b55-995d-2b43af4c8af1
Bukkit Callable executing lookup for: 55ba06d1-2f32-4b55-995d-2b43af4c8af1
Bukkit Callable finished. Player: CraftPlayer{name=DonutBunny}
Looking for author: ee4ed84d-3dee-4f6e-9f90-a0bc6da44dcf
Cache Load for Player: ee4ed84d-3dee-4f6e-9f90-a0bc6da44dcf
Bukkit Callable executing lookup for: ee4ed84d-3dee-4f6e-9f90-a0bc6da44dcf
Bukkit Callable finished. Player: CraftPlayer{name=NiceTeddyBear}
Looking for author: ee4ed84d-3dee-4f6e-9f90-a0bc6da44dcf
Cache Load for Player: ee4ed84d-3dee-4f6e-9f90-a0bc6da44dcf
Bukkit Callable executing lookup for: ee4ed84d-3dee-4f6e-9f90-a0bc6da44dcf
Bukkit Callable finished. Player: CraftPlayer{name=NiceTeddyBear}
Looking for author: 24e85fc2-876b-46f6-bfa7-63e1b40bcaf2
Cache Load for Player: 24e85fc2-876b-46f6-bfa7-63e1b40bcaf2
Sending Callable to bukkit
Task sent: org.bukkit.craftbukkit.v1_9_R1.scheduler.CraftFuture@5ca9423a
Looking for author: 24e85fc2-876b-46f6-bfa7-63e1b40bcaf2
[10:08:03] [Server thread/WARN]: [PwnFilter] Cache Load for Player: ee4ed84d-3dee-4f6e-9f90-a0bc6da44dcf
Bukkit Callable executing lookup for: ee4ed84d-3dee-4f6e-9f90-a0bc6da44dcf
Bukkit Callable finished. Player: CraftPlayer{name=NiceTeddyBear}
Looking for author: 55ba06d1-2f32-4b55-995d-2b43af4c8af1
Cache Load for Player: 55ba06d1-2f32-4b55-995d-2b43af4c8af1
Bukkit Callable executing lookup for: 55ba06d1-2f32-4b55-995d-2b43af4c8af1
Bukkit Callable finished. Player: CraftPlayer{name=DonutBunny}
Looking for author: ee4ed84d-3dee-4f6e-9f90-a0bc6da44dcf
Cache Load for Player: ee4ed84d-3dee-4f6e-9f90-a0bc6da44dcf
Bukkit Callable executing lookup for: ee4ed84d-3dee-4f6e-9f90-a0bc6da44dcf
Bukkit Callable finished. Player: CraftPlayer{name=NiceTeddyBear}
Looking for author: ee4ed84d-3dee-4f6e-9f90-a0bc6da44dcf
Cache Load for Player: ee4ed84d-3dee-4f6e-9f90-a0bc6da44dcf
Bukkit Callable executing lookup for: ee4ed84d-3dee-4f6e-9f90-a0bc6da44dcf
Bukkit Callable finished. Player: CraftPlayer{name=NiceTeddyBear}
Looking for author: 24e85fc2-876b-46f6-bfa7-63e1b40bcaf2
Cache Load for Player: 24e85fc2-876b-46f6-bfa7-63e1b40bcaf2
Sending Callable to bukkit
Task sent: org.bukkit.craftbukkit.v1_9_R1.scheduler.CraftFuture@5ca9423a
Looking for author: 24e85fc2-876b-46f6-bfa7-63e1b40bcaf2
[10:08:03] [Server thread/INFO]: [PwnFilter] Player Lookup failed: com.pwn9.filter.bukkit.BukkitAPI$PlayerNotFound
[10:08:03] [Async Chat Thread - #54/INFO]: [PwnFilter] Player Lookup failed: com.pwn9.filter.bukkit.BukkitAPI$PlayerNotFound
[10:08:03] [Server thread/INFO]: [PwnFilter] Cause: null
[10:08:03] [Async Chat Thread - #54/INFO]: [PwnFilter] Cause: null
[10:08:03] [Async Chat Thread - #54/INFO]: [PwnFilter] Filtering Aborted. Unable to lookup player in Chat Event. PlayerUUID: 24e85fc2-876b-46f6-bfa7-63e1b40bcaf2
[10:08:03] [Async Chat Thread - #54/INFO]: [PwnFilter] Message: connected with an iPhone using MineChat
[10:08:03] [Async Chat Thread - #54/INFO]: [PwnFilter] AuthorServices: [com.pwn9.filter.bukkit.BukkitAPI@265178cc]
[10:08:03] [Async Chat Thread - #54/INFO]: [PwnFilter] Bukkit player online: true
[10:08:03] [Async Chat Thread - #54/INFO]: <player>: connected with an iPhone using MineChat
[22:54:20] [Async Chat Thread - #72/WARN]: [PwnFilter] Bukkit API call timed out (Waited >10s!). Is the server busy?
[22:54:20] [Async Chat Thread - #72/WARN]: [PwnFilter] Task Cancelled?: false Task Done?: false
[22:54:20] [Async Chat Thread - #72/WARN]: [PwnFilter] Cache Load for Player: 6c175c1b-65bc-48e7-a6ec-09bfca8b73da
Sending Callable to bukkit
Task sent: org.bukkit.craftbukkit.v1_9_R1.scheduler.CraftFuture@6ccd0ca
Bukkit Callable executing lookup for: 6c175c1b-65bc-48e7-a6ec-09bfca8b73da
Bukkit Callable finished. Player: CraftPlayer{name=orangeyman8}
Sending Callable to bukkit
Task sent: org.bukkit.craftbukkit.v1_9_R1.scheduler.CraftFuture@396eca16
Looking for author: 6c175c1b-65bc-48e7-a6ec-09bfca8b73da
Cache Load for Player: 6c175c1b-65bc-48e7-a6ec-09bfca8b73da
Sending Callable to bukkit
Task sent: org.bukkit.craftbukkit.v1_9_R1.scheduler.CraftFuture@1eb35b5d
Bukkit Callable executing lookup for: 6c175c1b-65bc-48e7-a6ec-09bfca8b73da
Bukkit Callable finished. Player: CraftPlayer{name=orangeyman8}
Sending Callable to bukkit
Task sent: org.bukkit.craftbukkit.v1_9_R1.scheduler.CraftFuture@67519590
Looking for author: 750bd628-dd40-4e61-a82c-6cf43ab12994
Cache Load for Player: 750bd628-dd40-4e61-a82c-6cf43ab12994
Sending Callable to bukkit
Task sent: org.bukkit.craftbukkit.v1_9_R1.scheduler.CraftFuture@5f3ea8b1
Looking for author: 750bd628-dd40-4e61-a82c-6cf43ab12994
[22:54:20] [Server thread/WARN]: [PwnFilter] Cache Load for Player: 6c175c1b-65bc-48e7-a6ec-09bfca8b73da
Sending Callable to bukkit
Task sent: org.bukkit.craftbukkit.v1_9_R1.scheduler.CraftFuture@6ccd0ca
Bukkit Callable executing lookup for: 6c175c1b-65bc-48e7-a6ec-09bfca8b73da
Bukkit Callable finished. Player: CraftPlayer{name=orangeyman8}
Sending Callable to bukkit
Task sent: org.bukkit.craftbukkit.v1_9_R1.scheduler.CraftFuture@396eca16
Looking for author: 6c175c1b-65bc-48e7-a6ec-09bfca8b73da
Cache Load for Player: 6c175c1b-65bc-48e7-a6ec-09bfca8b73da
Sending Callable to bukkit
Task sent: org.bukkit.craftbukkit.v1_9_R1.scheduler.CraftFuture@1eb35b5d
Bukkit Callable executing lookup for: 6c175c1b-65bc-48e7-a6ec-09bfca8b73da
Bukkit Callable finished. Player: CraftPlayer{name=orangeyman8}
Sending Callable to bukkit
Task sent: org.bukkit.craftbukkit.v1_9_R1.scheduler.CraftFuture@67519590
Looking for author: 750bd628-dd40-4e61-a82c-6cf43ab12994
Cache Load for Player: 750bd628-dd40-4e61-a82c-6cf43ab12994
Sending Callable to bukkit
Task sent: org.bukkit.craftbukkit.v1_9_R1.scheduler.CraftFuture@5f3ea8b1
Looking for author: 750bd628-dd40-4e61-a82c-6cf43ab12994
[22:54:20] [Async Chat Thread - #72/INFO]: [PwnFilter] Player Lookup failed: com.pwn9.filter.bukkit.BukkitAPI$PlayerNotFound
[22:54:20] [Server thread/INFO]: [PwnFilter] Player Lookup failed: com.pwn9.filter.bukkit.BukkitAPI$PlayerNotFound
[22:54:20] [Async Chat Thread - #72/INFO]: [PwnFilter] Cause: null
[22:54:20] [Server thread/INFO]: [PwnFilter] Cause: null
[22:54:20] [Async Chat Thread - #72/INFO]: [PwnFilter] Filtering Aborted. Unable to lookup player in Chat Event. PlayerUUID: 750bd628-dd40-4e61-a82c-6cf43ab12994
[22:54:20] [Async Chat Thread - #72/INFO]: [PwnFilter] Message: noice
[22:54:20] [Async Chat Thread - #72/INFO]: [PwnFilter] AuthorServices: [com.pwn9.filter.bukkit.BukkitAPI@1f8ba605]
[22:54:20] [Async Chat Thread - #72/INFO]: [PwnFilter] Bukkit player online: true
Thanks, mibby. I now understand what the problem is. I am going to fix this shortly.
I hoped to have it fixed by now, but it is a race condition, so I have to
write some tests that use threads, first. It is taking a bit more time
than I would like. I hope to have it fixed tonight.
Damn... Writing the test for that took longer than the fix. :) I'm pretty confident that this has resolved the issue. Please feel free to tell me I'm wrong. :)
119
@ptoal :( On build 119. Thought everything was in the clear, but then this error occurred.
[00:41:33] [Async Chat Thread - #67/WARN]: [PwnFilter] Bukkit API call timed out (Waited >3s). Is the server busy?
[00:41:33] [Async Chat Thread - #67/ERROR]: Could not pass event AsyncPlayerChatEvent to PwnFilter v3.9.2-SNAPSHOT-b119
java.lang.NullPointerException
at com.pwn9.filter.bukkit.listener.PwnFilterPlayerListener.onPlayerChat(PwnFilterPlayerListener.java:76) ~[?:?]
at com.pwn9.filter.bukkit.listener.PwnFilterPlayerListener.lambda$activate$30(PwnFilterPlayerListener.java:140) ~[?:?]
at co.aikar.timings.TimedEventExecutor.execute(TimedEventExecutor.java:74) ~[patched_1.9.4.jar:git-Paper-733]
at org.bukkit.plugin.RegisteredListener.callEvent(RegisteredListener.java:62) ~[patched_1.9.4.jar:git-Paper-733]
at org.bukkit.plugin.SimplePluginManager.fireEvent(SimplePluginManager.java:517) [patched_1.9.4.jar:git-Paper-733]
at org.bukkit.plugin.SimplePluginManager.callEvent(SimplePluginManager.java:499) [patched_1.9.4.jar:git-Paper-733]
at net.minecraft.server.v1_9_R2.PlayerConnection.chat(PlayerConnection.java:1302) [patched_1.9.4.jar:git-Paper-733]
at net.minecraft.server.v1_9_R2.PlayerConnection.a(PlayerConnection.java:1217) [patched_1.9.4.jar:git-Paper-733]
at net.minecraft.server.v1_9_R2.PacketPlayInChat$1.run(PacketPlayInChat.java:39) [patched_1.9.4.jar:git-Paper-733]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_92]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_92]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:1.8.0_92]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:1.8.0_92]
at java.lang.Thread.run(Thread.java:745) [?:1.8.0_92]
Build #120 is available, which should resolve this issue.
Well, there's good news and bad news here. :) The good news is that the original issue looks like it is fixed. The bad news is that it looks like there is a similar blocking issue in the permission cache. The good news is that I can fix it in a similar way, and should be able to do so fairly quickly. :)
@ptoal The jenkins server is asking me to login now. Can't download the build. :(
Try again, now?
On May 13, 2016 10:42 PM, "mibby" [email protected] wrote:
@ptoal https://github.com/ptoal The jenkins server is asking me to
login now. Can't download the build. :(
@ptoal Yep, sorry. Let it ran for a few days to collect data. Everything seems great now! Just noticed this minor issue when someone entered special characters into chat.
[03:48:05] [Async Chat Thread - #52/ERROR]: [PwnFilter] Regex match timed out! Regex: ([^0-9)])(?=\1\1\1\1+)
[03:48:05] [Async Chat Thread - #52/ERROR]: [PwnFilter] Failed string was: 🍎🍎🍎
Okay, I'm going to close this ticket, then. It's a bit long in the tooth. :)
I looked into the other error. I'm actually not correctly reporting the issue, there. I'm saying that the Regex timed out, but it didn't. In fact, this is just exposing a bug with Java's regex engine: https://stackoverflow.com/questions/16008974/strange-java-unicode-regular-expression-stringindexoutofboundsexception
I'm just going to eat that other error, for now. It won't match on those characters, anyway.
Sounds good. Thanks for fixing the error. :) I'll let you know if I run into any other problems.
@ptoal Going through logs, found another error!
Edit: Opened ticket here. #23
10:49:07] [Async Chat Thread - #61/WARN]: [PwnFilter] Bukkit API call timed out (Waited >3s). Is the server busy?
[10:49:07] [Async Chat Thread - #61/ERROR]: Could not pass event AsyncPlayerChatEvent to PwnFilter v3.9.2-SNAPSHOT-b121
java.lang.NullPointerException
at java.util.concurrent.ConcurrentHashMap.putVal(ConcurrentHashMap.java:1011) ~[?:1.8.0_92]
at java.util.concurrent.ConcurrentHashMap.putIfAbsent(ConcurrentHashMap.java:1535) ~[?:1.8.0_92]
at com.pwn9.filter.bukkit.BukkitPlayer.hasPermission(BukkitPlayer.java:75) ~[?:?]
at com.pwn9.filter.bukkit.listener.PwnFilterPlayerListener.onPlayerChat(PwnFilterPlayerListener.java:76) ~[?:?]
at com.pwn9.filter.bukkit.listener.PwnFilterPlayerListener.lambda$activate$29(PwnFilterPlayerListener.java:140) ~[?:?]
at co.aikar.timings.TimedEventExecutor.execute(TimedEventExecutor.java:74) ~[patched_1.9.4.jar:git-Paper-748]
at org.bukkit.plugin.RegisteredListener.callEvent(RegisteredListener.java:62) ~[patched_1.9.4.jar:git-Paper-748]
at org.bukkit.plugin.SimplePluginManager.fireEvent(SimplePluginManager.java:517) [patched_1.9.4.jar:git-Paper-748]
at org.bukkit.plugin.SimplePluginManager.callEvent(SimplePluginManager.java:499) [patched_1.9.4.jar:git-Paper-748]
at net.minecraft.server.v1_9_R2.PlayerConnection.chat(PlayerConnection.java:1302) [patched_1.9.4.jar:git-Paper-748]
at net.minecraft.server.v1_9_R2.PlayerConnection.a(PlayerConnection.java:1217) [patched_1.9.4.jar:git-Paper-748]
at net.minecraft.server.v1_9_R2.PacketPlayInChat$1.run(PacketPlayInChat.java:39) [patched_1.9.4.jar:git-Paper-748]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_92]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_92]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:1.8.0_92]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:1.8.0_92]
at java.lang.Thread.run(Thread.java:745) [?:1.8.0_92]