CME on Netty Server IO Thread #96

ams2990 · 2015-11-04T03:40:22Z

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.

The text was updated successfully, but these errors were encountered:

dmulloy2 · 2015-11-06T23:39:18Z

This looks to be the same issue as dmulloy2/ProtocolLib#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 · 2015-11-07T17:32:35Z

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

ams2990 · 2015-11-07T18:28:12Z

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 · 2015-11-14T16:39:34Z

Any more info on this?

ams2990 · 2015-11-15T07:48:40Z

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 · 2015-11-24T20:32:55Z

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

ams2990 · 2015-12-06T04:14:01Z

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 · 2015-12-06T04:15:57Z

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 · 2015-12-06T18:33:21Z

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 · 2016-04-03T04:39:47Z

Any more information on this?

ams2990 · 2016-04-07T03:15:52Z

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

Kneesnap · 2019-01-05T05:23:29Z

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

Kneesnap · 2019-01-05T07:23:11Z

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

Protonull · 2020-06-27T11:53:23Z

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 · 2020-06-27T12:25:58Z

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 ***@***.***> 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 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) — You are receiving this because you commented. Reply to this email directly, view it on GitHub <#96 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/ABSCIYOXPMWFFMJVW2UNUTTRYXMT7ANCNFSM4BTN23WQ> .

Protonull · 2020-06-27T17:22:25Z

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

dmulloy2 · 2020-06-27T21:35:13Z

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 · 2020-06-27T21:51:19Z

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 · 2020-06-30T00:30:05Z

@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 · 2020-07-07T07:25:41Z

@dmulloy2 thoughts?

dmulloy2 · 2020-07-26T03:56:19Z

@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 · 2020-07-26T04:03:47Z

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 · 2022-06-01T16:48:12Z

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 · 2022-10-11T08:18:51Z

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 <#96 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/ABSCIYIHHESOXJ6GTH3DABLR5OSO5ANCNFSM4BTN23WQ> .

dmulloy2 added the bug label Nov 6, 2015

dmulloy2 self-assigned this Nov 6, 2015

ams2990 closed this as completed Apr 7, 2016

Kneesnap mentioned this issue May 26, 2020

ConcurrentModificationException Kicks Player without Stack Trace #176

Closed

dmulloy2 reopened this Jun 27, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

CME on Netty Server IO Thread #96

CME on Netty Server IO Thread #96

ams2990 commented Nov 4, 2015

dmulloy2 commented Nov 6, 2015

dmulloy2 commented Nov 7, 2015

ams2990 commented Nov 7, 2015

dmulloy2 commented Nov 14, 2015

ams2990 commented Nov 15, 2015

dmulloy2 commented Nov 24, 2015

ams2990 commented Dec 6, 2015

ams2990 commented Dec 6, 2015

dmulloy2 commented Dec 6, 2015

dmulloy2 commented Apr 3, 2016

ams2990 commented Apr 7, 2016

Kneesnap commented Jan 5, 2019

Kneesnap commented Jan 5, 2019

Protonull commented Jun 27, 2020

Kneesnap commented Jun 27, 2020 via email

Protonull commented Jun 27, 2020

dmulloy2 commented Jun 27, 2020

Protonull commented Jun 27, 2020

Kneesnap commented Jun 30, 2020 •

edited

Loading

Protonull commented Jul 7, 2020

dmulloy2 commented Jul 26, 2020

Kneesnap commented Jul 26, 2020

MWHunter commented Jun 1, 2022

Kneesnap commented Oct 11, 2022 via email

CME on Netty Server IO Thread #96

CME on Netty Server IO Thread #96

Comments

ams2990 commented Nov 4, 2015

dmulloy2 commented Nov 6, 2015

dmulloy2 commented Nov 7, 2015

ams2990 commented Nov 7, 2015

dmulloy2 commented Nov 14, 2015

ams2990 commented Nov 15, 2015

dmulloy2 commented Nov 24, 2015

ams2990 commented Dec 6, 2015

ams2990 commented Dec 6, 2015

dmulloy2 commented Dec 6, 2015

dmulloy2 commented Apr 3, 2016

ams2990 commented Apr 7, 2016

Kneesnap commented Jan 5, 2019

Kneesnap commented Jan 5, 2019

Protonull commented Jun 27, 2020

Kneesnap commented Jun 27, 2020 via email

Protonull commented Jun 27, 2020

dmulloy2 commented Jun 27, 2020

Protonull commented Jun 27, 2020

Kneesnap commented Jun 30, 2020 • edited Loading

Protonull commented Jul 7, 2020

dmulloy2 commented Jul 26, 2020

Kneesnap commented Jul 26, 2020

MWHunter commented Jun 1, 2022

Kneesnap commented Oct 11, 2022 via email

Kneesnap commented Jun 30, 2020 •

edited

Loading