CME on Netty Server IO Thread

[ams2990]

I'm listening to PacketType.Play.Server.ENTITY_EQUIPMENT packets and editing the contents to remove information that Mojang never should send to clients. You can the code I'm using here.

I have observed that players occasionally disconnect with the following super helpful log entries:

[20:37:20] [Netty Server IO #2/ERROR]: java.util.ConcurrentModificationException 
[20:37:20] [Server thread/INFO]: DeathWalking lost connection: Disconnected
[20:37:20] [Server thread/INFO]: DeathWalking left the game.

It's pretty hard to reproduce, unfortunately. It seems to reproduce more often during PvP, so I gathered four other people on a test server, spawned a bunch of armor and pots, and whacked each other for a while. We got screenshots of the client disconnect message, two very similar ones: http://imgur.com/a/etwzX.

I'm not just sure where the fault lies. My guess is something on the Netty threads is throwing the CME and the packet that's being sent to the client is malformed, causing the disconnect.

[dmulloy2]

This looks to be the same issue as https://github.com/dmulloy2/ProtocolLib/issues/36. Can you set debug=true in the server.properties and debug: true in the ProtocolLib config? It should print out a (more) helpful message.

[dmulloy2]

That code didn't seem to work. I modified it a bit here and didn't get any CME's.

[ams2990]

Like I said, it's hard to reproduce. It tends to happen in groups, but I can't quite figure out exactly what triggers it. When I did get the above error, I had ProtocolLib debug: true. I didn't have Minecraft debug=true, but I'll have to try that and see if I get anything more interesting.

[dmulloy2]

Any more info on this?

[ams2990]

Sorry, my free time has been consumed by Starcraft and Fallout :-)

I'll set debug=true on the main server and see what happens.

[dmulloy2]

I'd like to get this fixed before releasing 3.6.5, can I get the debug info?

[ams2990]

Sorry for the delayed response. I've had debug=true on and haven't gotten any more info. I got one earlier today and all we get is the name of the exception. No trace body :/

[ams2990]

Given how infrequently this reproduces, my guess is that this is a race condition. Is it possible the packet is being read so it can be sent while I'm still modifying it?

[dmulloy2]

It could be a race condition, but ProtocolLib should hold on to the packet until you're finished modifying it. It's likely that the CME is internal (PL or Minecraft itself), since any exceptions from onPacketSending and onPacketReceiving should be caught by PL. Unfortunately, there's not much I can do without a stack body :/

[dmulloy2]

Any more information on this?

[ams2990]

Sorry, I couldn't get any useful debugging information. I eventually just disabled the feature, since it wasn't worth disconnecting users over.

[Kneesnap]

I'm having this issue too, interestingly also with ENTITY_EQUIPMENT. Sometimes it's NullPointerException, sometimes its ConcurrentModificationException. It's really frustrating.

[Kneesnap]

It stopped kicking players after I stopped messing with ItemMeta, however this is not an optimal solution.

[Protonull]

We've been facing the same error on our server and concur that it seems to happen more frequently with groups of players. We have a plugin that hides certain data from players' armour to diminish the benefit of certain pvp mods, and part of that process includes modifying ItemMeta.

Here's a full stack trace:

[02:44:24 ERROR]: java.util.ConcurrentModificationException
[02:44:24 WARN]: java.util.ConcurrentModificationException
[02:44:24 WARN]:        at java.util.HashMap$HashIterator.nextNode(HashMap.java:1445)
[02:44:24 WARN]:        at java.util.HashMap$KeyIterator.next(HashMap.java:1469)
[02:44:24 WARN]:        at net.minecraft.server.v1_14_R1.NBTTagCompound.clone(NBTTagCompound.java:382)
[02:44:24 WARN]:        at net.minecraft.server.v1_14_R1.ItemStack.cloneItemStack(ItemStack.java:492)
[02:44:24 WARN]:        at net.minecraft.server.v1_14_R1.ItemStack.cloneItemStack(ItemStack.java:486)
[02:44:24 WARN]:        at net.minecraft.server.v1_14_R1.PacketDataSerializer.a(PacketDataSerializer.java:254)
[02:44:24 WARN]:        at net.minecraft.server.v1_14_R1.PacketPlayOutEntityEquipment.b(SourceFile:35)
[02:44:24 WARN]:        at net.minecraft.server.v1_14_R1.PacketEncoder.encode(PacketEncoder.java:42)
[02:44:24 WARN]:        at net.minecraft.server.v1_14_R1.PacketEncoder.encode(PacketEncoder.java:12)
[02:44:24 WARN]:        at sun.reflect.GeneratedMethodAccessor20.invoke(Unknown Source)
[02:44:24 WARN]:        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[02:44:24 WARN]:        at java.lang.reflect.Method.invoke(Method.java:498)
[02:44:24 WARN]:        at com.comphenix.protocol.reflect.accessors.DefaultMethodAccessor.invoke(DefaultMethodAccessor.java:16)
[02:44:24 WARN]:        at com.comphenix.protocol.injector.netty.ChannelInjector.encode(ChannelInjector.java:455)
[02:44:24 WARN]:        at com.comphenix.protocol.injector.netty.ChannelInjector.access$100(ChannelInjector.java:63)
[02:44:24 WARN]:        at com.comphenix.protocol.injector.netty.ChannelInjector$1.encode(ChannelInjector.java:229)
[02:44:24 WARN]:        at io.netty.handler.codec.MessageToByteEncoder.write(MessageToByteEncoder.java:107)
[02:44:24 WARN]:        at com.comphenix.protocol.injector.netty.ChannelInjector$1.write(ChannelInjector.java:235)
[02:44:24 WARN]:        at io.netty.channel.AbstractChannelHandlerContext.invokeWrite0(AbstractChannelHandlerContext.java:738)
[02:44:24 WARN]:        at io.netty.channel.AbstractChannelHandlerContext.invokeWriteAndFlush(AbstractChannelHandlerContext.java:801)
[02:44:24 WARN]:        at io.netty.channel.AbstractChannelHandlerContext.write(AbstractChannelHandlerContext.java:814)
[02:44:24 WARN]:        at io.netty.channel.AbstractChannelHandlerContext.writeAndFlush(AbstractChannelHandlerContext.java:794)
[02:44:24 WARN]:        at io.netty.channel.AbstractChannelHandlerContext.writeAndFlush(AbstractChannelHandlerContext.java:831)
[02:44:24 WARN]:        at io.netty.channel.DefaultChannelPipeline.writeAndFlush(DefaultChannelPipeline.java:1071)
[02:44:24 WARN]:        at io.netty.channel.AbstractChannel.writeAndFlush(AbstractChannel.java:300)
[02:44:24 WARN]:        at com.comphenix.protocol.injector.netty.ChannelProxy.writeAndFlush(ChannelProxy.java:327)
[02:44:24 WARN]:        at net.minecraft.server.v1_14_R1.NetworkManager.lambda$b$4(NetworkManager.java:205)
[02:44:24 WARN]:        at com.comphenix.protocol.injector.netty.ChannelInjector$3.lambda$onMessageScheduled$1(ChannelInjector.java:307)
[02:44:24 WARN]:        at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:163)
[02:44:24 WARN]:        at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:404)
[02:44:24 WARN]:        at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:313)
[02:44:24 WARN]:        at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:884)
[02:44:24 WARN]:        at java.lang.Thread.run(Thread.java:748)

[Kneesnap]

Huh, interesting. I should add that my server also modified item NBT with a packet listener, though I would have though I do find it a little strange if that's indeed the cause, because it should be working with cloned ItemStacks?

On Sat, Jun 27, 2020, 4:53 AM Alexander notifications@github.com wrote:

We've been facing the same error on our server and concur that it seems to happen more frequently with groups of players. We have a plugin that hides certain data from players' armour to diminish the benefit of certain pvp mods, and part of that process includes modifying ItemMeta.

Here's a full stack trace:

02:44:24 WARN: at java.util.HashMap$HashIterator.nextNode(HashMap.java:1445) 02:44:24 WARN: at java.util.HashMap$KeyIterator.next(HashMap.java:1469) 02:44:24 WARN: at net.minecraft.server.v1_14_R1.NBTTagCompound.clone(NBTTagCompound.java:382) 02:44:24 WARN: at net.minecraft.server.v1_14_R1.ItemStack.cloneItemStack(ItemStack.java:492) 02:44:24 WARN: at net.minecraft.server.v1_14_R1.ItemStack.cloneItemStack(ItemStack.java:486) 02:44:24 WARN: at net.minecraft.server.v1_14_R1.PacketDataSerializer.a(PacketDataSerializer.java:254) 02:44:24 WARN: at net.minecraft.server.v1_14_R1.PacketPlayOutEntityEquipment.b(SourceFile:35) 02:44:24 WARN: at net.minecraft.server.v1_14_R1.PacketEncoder.encode(PacketEncoder.java:42) 02:44:24 WARN: at net.minecraft.server.v1_14_R1.PacketEncoder.encode(PacketEncoder.java:12) 02:44:24 WARN: at sun.reflect.GeneratedMethodAccessor20.invoke(Unknown Source) 02:44:24 WARN: at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) 02:44:24 WARN: at java.lang.reflect.Method.invoke(Method.java:498) 02:44:24 WARN: at com.comphenix.protocol.reflect.accessors.DefaultMethodAccessor.invoke(DefaultMethodAccessor.java:16) 02:44:24 WARN: at com.comphenix.protocol.injector.netty.ChannelInjector.encode(ChannelInjector.java:455) 02:44:24 WARN: at com.comphenix.protocol.injector.netty.ChannelInjector.access$100(ChannelInjector.java:63) 02:44:24 WARN: at com.comphenix.protocol.injector.netty.ChannelInjector$1.encode(ChannelInjector.java:229) 02:44:24 WARN: at io.netty.handler.codec.MessageToByteEncoder.write(MessageToByteEncoder.java:107) 02:44:24 WARN: at com.comphenix.protocol.injector.netty.ChannelInjector$1.write(ChannelInjector.java:235) 02:44:24 WARN: at io.netty.channel.AbstractChannelHandlerContext.invokeWrite0(AbstractChannelHandlerContext.java:738) 02:44:24 WARN: at io.netty.channel.AbstractChannelHandlerContext.invokeWriteAndFlush(AbstractChannelHandlerContext.java:801) 02:44:24 WARN: at io.netty.channel.AbstractChannelHandlerContext.write(AbstractChannelHandlerContext.java:814) 02:44:24 WARN: at io.netty.channel.AbstractChannelHandlerContext.writeAndFlush(AbstractChannelHandlerContext.java:794) 02:44:24 WARN: at io.netty.channel.AbstractChannelHandlerContext.writeAndFlush(AbstractChannelHandlerContext.java:831) 02:44:24 WARN: at io.netty.channel.DefaultChannelPipeline.writeAndFlush(DefaultChannelPipeline.java:1071) 02:44:24 WARN: at io.netty.channel.AbstractChannel.writeAndFlush(AbstractChannel.java:300) 02:44:24 WARN: at com.comphenix.protocol.injector.netty.ChannelProxy.writeAndFlush(ChannelProxy.java:327) 02:44:24 WARN: at net.minecraft.server.v1_14_R1.NetworkManager.lambda$b$4(NetworkManager.java:205) 02:44:24 WARN: at com.comphenix.protocol.injector.netty.ChannelInjector$3.lambda$onMessageScheduled$1(ChannelInjector.java:307) 02:44:24 WARN: at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:163) 02:44:24 WARN: at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:404) 02:44:24 WARN: at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:313) 02:44:24 WARN: at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:884) 02:44:24 WARN: at java.lang.Thread.run(Thread.java:748)

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/aadnk/ProtocolLib/issues/96#issuecomment-650550480, or unsubscribe https://github.com/notifications/unsubscribe-auth/ABSCIYOXPMWFFMJVW2UNUTTRYXMT7ANCNFSM4BTN23WQ .

[Protonull]

@dmulloy2 Sorry for ping, not sure if you got a notification since I'm reviving pretty much a four years dead thread

[dmulloy2]

seems to be NBT that isn’t properly cloned and getting modified on different threads. @Protonull or @Kneesnap can one of y’all provide some code?

[Protonull]

Not sure what you mean by provide some code. We have an Ansible setup that'll create a clone of our server, but you'd likely need a group of people to reproduce the exception. The plugin that seemed to be causing the problem was AttrHider.

[Kneesnap]

@dmulloy2 I can provide some code.

package net.dungeonrealms.mechanics;

import com.comphenix.protocol.PacketType;
import com.comphenix.protocol.ProtocolLibrary;
import com.comphenix.protocol.events.PacketAdapter;
import com.comphenix.protocol.events.PacketEvent;
import com.google.common.collect.Sets;
import net.dungeonrealms.Core;
import net.dungeonrealms.item.ItemManager;
import net.dungeonrealms.item.ItemWrapper;
import net.dungeonrealms.mechanics.system.Mechanic;
import net.dungeonrealms.utils.Utils;
import net.minecraft.server.v1_12_R1.NBTTagCompound;
import org.bukkit.inventory.ItemStack;

import java.util.Set;
/**
 * Prevents players from using mods to learn what items are on mobs.
 * Created by Kneesnap on 1/18/2018.
 */
public class MobESPFixer extends Mechanic {
    private static final Set<String> ALLOWED_TAGS = Sets.newHashSet("SkullOwner", "ench", ItemManager.ITEM_NAME, "BlockEntityTag");

    @Override
    public void onEnable() {
        ProtocolLibrary.getProtocolManager().addPacketListener(new PacketAdapter(Core.getInstance(), PacketType.Play.Server.ENTITY_EQUIPMENT) {
            @Override
            public void onPacketSending(PacketEvent event) {
                ItemStack item = event.getPacket().getItemModifier().read(0);
                if (Utils.notAir(item))
                    stripItem(item);
            }
        });
    }

    private static void stripItem(ItemStack item) {
        NBTTagCompound nbtTag = ItemWrapper.getCraftNBTTag(item);
        if (nbtTag != null)
            nbtTag.map.entrySet().removeIf(entry -> !ALLOWED_TAGS.contains(entry.getKey()));
    }
}

Utils.notAir

return item != null && item.getType() != Material.AIR;

ItemWrapper.getCraftNBTTag:

if (!(item instanceof CraftItemStack))
    throw new GeneralException("Item passed was not actually a CraftItem!");
return get nbt tag from nms item stack, if it has one.

[Protonull]

@dmulloy2 thoughts?

[dmulloy2]

@Kneesnap Try cloning the NBT tag before modifying it. My guess is that the same instance is getting passed around and the netty threads don't like the concurrent modifications.

[Kneesnap]

I'll try that, but I'm somewhat skeptical. If this was editing the same data used in other places, the actual items in the game should have been modified, at least given my understanding of NMS.

[MWHunter]

This packet gets sent to multiple people, meaning it is being processed by multiple netty threads. Modifying this packet will modify the packet for everyone this packet is being sent to and should be avoided.

[Kneesnap]

It had to do with skulls regardless of cloning. Skulls would fetch skin data and update tags upon referring it inside CraftBukkit code on a separate thread.

On Sat, Jul 25, 2020, 8:56 PM Dan Mulloy @.***> wrote:

@Kneesnap https://github.com/Kneesnap Try cloning the NBT tag before modifying it. My guess is that the same instance is getting passed around and the netty threads don't like the concurrent modifications.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/aadnk/ProtocolLib/issues/96#issuecomment-663932520, or unsubscribe https://github.com/notifications/unsubscribe-auth/ABSCIYIHHESOXJ6GTH3DABLR5OSO5ANCNFSM4BTN23WQ .