[MC-79154] Hoppers occasionally duplicate items

Server duplicates items in hoppers. After a while, all hopper clocks are getting broken, because there is more than one item in it. I managed to duplicate diamond blocks.

Server Console says:

[13:01:44] [Server thread/WARN]: Fetching addPacket for removed entity
[13:01:44] [Server thread/WARN]: Fetching addPacket for removed entity
[13:01:44] [Server thread/WARN]: Fetching addPacket for removed entity
[13:01:44] [Server thread/WARN]: Fetching addPacket for removed entity
[13:01:44] [Server thread/WARN]: Fetching addPacket for removed entity
[13:01:44] [Server thread/WARN]: Fetching addPacket for removed entity
[13:01:44] [Server thread/WARN]: Fetching addPacket for removed entity
[13:02:23] [Server thread/WARN]: Can't keep up! Did the system time change, or is the server overloaded? Running 2144ms behind, skipping 42 tick(s)

Edit: I now caught it happening. A hopper speed up so fast, that even a comparator doesn't work anymore. I'm sure this leads to item duplication.

Code analisys by @unknown can be found in this comment.

Linked issues

relates to 2

MC-78155 Random Hopper speed Resolved

MC-102348 Order of chunk unloading, executing commands and removing unloaded entities causes problems Resolved

testing discovered 1

MC-119971 Various duplications, deletions, and data corruption at chunk boundaries, caused by loading outdated chunks — includes duping and deletion of entities/mobs, items in hoppers, and blocks moved by pistons, among other problems Resolved

Attachments

crash-2015-03-30_20.03.02-client.txt

Comments 18

kumasasa 2015-03-30T17:13:31Z

After having this issue:
Please force a crash by pressing F3 + C for 10 seconds while in-game and attach the crash report ([minecraft/crash-reports/crash-<DATE>-client.txt|http://hopper.minecraft.net/help/finding-minecraft-data-folder]) here.

Ole 2015-03-30T18:01:56Z

This is a payed 14/7 Server, I will try my best to catch the issue happening.
Are you sure it is client releated? Also I've found this Bug-Report: (MC-78155) In the comments people say this speed up could cause duplication.

Ole 2015-03-30T18:04:26Z

Log of forced crash

Autopoietico 2015-05-27T01:16:24Z

I see this bug in chunks charged with redstone and lazychunks.

Martin Bittermann 2015-08-22T15:30:37Z

Can confirm this. We had a lot of hopper pairs facing into each other across chunk borders on or SMP server, in an attempt to create chunk loaders. We had a single item of cobblestone oscillating in each hopper pair. Upon inspection after a few weeks, most hoppers had 2-4 stacks of cobblestone. I first thought those had been left there on accident, when digging the tunnels, but turns out this was the item duplication bug. Then I recreated the setup in our base, with 3 pairs of hoppers, two of them at a chunk border, with different items, one item per pair. All three had about 4-7 items in each hopper, overnight.
I'm not sure whether it has something to do with the server messages "[Server thread/WARN]: Fetching addPacket for removed entity". I had some of these, too, but only 3 that night. One other player was logged into the server at that time.

8 more comments

John Trainer 2015-11-11T03:33:36Z

I can confirm that this happens in 15w45a in SMP.

marcono1234 2015-12-14T16:22:36Z

I do not know if this is related to this, but in Minecraft 1.8 (decompiled using MCP) the server would still send packets for dead entities. It should probably rather not send packets in this case.

if (this.trackedEntity.isDead)
{
	// This should return null as the entity is already dead
	logger.warn("Fetching addPacket for removed entity");
	// Added the following line
	return null;
}

This returned null needs to be tested for later on in the updatePlayerEntity(EntityPlayerMP p_73117_1_) method of the net.minecraft.entity.EntityTrackerEntry class.

Packet var2 = this.func_151260_c();
// null is now returned if the entity is already dead
// Added the following line
if (var2 == null) return;

KevinTheDruid 2016-03-04T14:53:59Z

Affects 1.9

wobst.michael 2016-10-23T15:15:20Z

Is this still an issue in the most recent versions (currently that is 1.10.2, or 16w42a) of Minecraft? If so, please update the affected versions and help us keeping this ticket updated from time to time. If you are the owner/reporter of this ticket, you can modify the affected version(s) yourself.

ragou42 2017-05-02T06:27:43Z

At the chance of "necroing" this: It was always an issue and still is (1.11.2 for sure, snapshots extremely likely but would need to test)

Timothy Miller 2017-08-02T03:27:04Z

Doing experiments with MCP, I've figured out why hoppers are duping items.

My experiments are based on what I saw in Gnembon's video (https://www.youtube.com/watch?v=q6r6lfc6o0o), and I can reliably get items to dupe by causing chunks containing hopper pairs to load and unload over and over again. Because the conditions are controlled, I could keep a rolling log of relevant activity and then dump it out the instant that a hopper pair was detected with more than one item between them. Below is excerpts from a log that demonstrates the problem happening. (Markdown makes some of the pastes look wrong.)

// We get a chunk unloading on game tick 1363398.  But it's actually tick 1363399 because of when worldTotalTime is incremented.

unloadQueuedChunks 1363398
...

// And the 587th TileEntityHopper object created is among them (remember, this is really tick 1363399)

Hopper save on tick 1363398 ser=587 oser=3
  Position at co{x=-8, y=56, z=7}
    data: {TransferCooldown:1,x:-8,y:56,z:7,Items:[0:{Slot:0b,id:"minecraft:redstone",Count:1b,Damage:0s}],id:"minecraft:hopper",serial_num:3L,Lock:""}
...

// On the very same tick, that chunk is reloaded, with the hopper having a new identity as the 593rd TileEntityHopper object.

Hopper load on tick 1363399 ser=593 oser=3
  Position at co{x=-8, y=56, z=7}
    data: {TransferCooldown:1,x:-8,y:56,z:7,Items:[0:{Slot:0b,id:"minecraft:redstone",Count:1b,Damage:0s}],id:"minecraft:hopper",serial_num:3L,Lock:""}
...

// But for some reason, #587 still exists in worldserver.tickableTileEntities.  Coincidentally, its cooldown timer runs out, so it gets ticked, transferring an item to its neighboring hopper.

Hopper transfer on tick 1363399 ser=587 oser=3
  Source at co{x=-8, y=56, z=7}
    prev: {TransferCooldown:1,x:-8,y:56,z:7,Items:[0:{Slot:0b,id:"minecraft:redstone",Count:1b,Damage:0s}],id:"minecraft:hopper",serial_num:3L,Lock:""}
    next: {TransferCooldown:8,x:-8,y:56,z:7,Items:[],id:"minecraft:hopper",serial_num:3L,Lock:""}
  Target at co{x=-8, y=56, z=8}
    prev: {TransferCooldown:2,x:-8,y:56,z:8,Items:[],id:"minecraft:hopper",serial_num:4L,Lock:""}
    next: {TransferCooldown:8,x:-8,y:56,z:8,Items:[0:{Slot:0b,id:"minecraft:redstone",Count:1b,Damage:0s}],id:"minecraft:hopper",serial_num:4L,Lock:""}
...

// Finally, #587 is removed from the list:

tickableTileEntities.removeAll 1363399
...

// Subsequently the NEW hopper at these coordinates is ticked, adding an extra item to the neighboring hopper.

Hopper transfer on tick 1363400 ser=593 oser=3
  Source at co{x=-8, y=56, z=7}
    prev: {TransferCooldown:1,x:-8,y:56,z:7,Items:[0:{Slot:0b,id:"minecraft:redstone",Count:1b,Damage:0s}],id:"minecraft:hopper",serial_num:3L,Lock:""}
    next: {TransferCooldown:8,x:-8,y:56,z:7,Items:[],id:"minecraft:hopper",serial_num:3L,Lock:""}
  Target at co{x=-8, y=56, z=8}
    prev: {TransferCooldown:8,x:-8,y:56,z:8,Items:[0:{Slot:0b,id:"minecraft:redstone",Count:1b,Damage:0s}],id:"minecraft:hopper",serial_num:4L,Lock:""}
    next: {TransferCooldown:8,x:-8,y:56,z:8,Items:[0:{Slot:0b,id:"minecraft:redstone",Count:2b,Damage:0s}],id:"minecraft:hopper",serial_num:4L,Lock:""}
...

The trick is to get a chunk to unload, reload, and have a hopper's cooldown timer expire, all on the same game tick.

Here's why this goes wrong:

MinecraftServer.updateTimeLightAndEntities first calls worldserver.tick, then worldserver.updateEntities.
WorldServer.tick calls chunkProvider.unloadQueuedChunks, which adds all the tile entities to be unloaded to world.tileEntitiesToBeRemoved.
NOTE: After that, this happens in WorldServer.tick, throwing off the tick numbers for us:
this.worldInfo.setWorldTotalTime(this.worldInfo.getWorldTotalTime() + 1L);
Then in worldserver.updateEntities, it first iterates through all tickableTileEntities, and THEN deletes all those listed in tileEntitiesToBeRemoved.

This ordering is wrong. Any tile entity that is scheduled to be removed should NOT get ticked.

The SOLUTION is to move this in World.updateEntities:

if (!this.tileEntitiesToBeRemoved.isEmpty())
        {
            this.tickableTileEntities.removeAll(this.tileEntitiesToBeRemoved);
            this.loadedTileEntityList.removeAll(this.tileEntitiesToBeRemoved);
            this.tileEntitiesToBeRemoved.clear();
        }

To above this:

this.theProfiler.endStartSection("blockEntities");
        this.processingLoadedTiles = true;
        Iterator<TileEntity> iterator = this.tickableTileEntities.iterator();

        while (iterator.hasNext())
        {
            TileEntity tileentity = (TileEntity)iterator.next();
            ...

I'll be testing this over night to make sure it works. Also, we really need to look around for any other such ordering reversals.

gnembon 2017-08-02T08:38:50Z

Indeed this works! I was initially suspecting some more crazy stuff causing it, but the hopper code seemed to be clean, and the actual reason happened to be more trivial than everybody suspected. since tileEntitiesToBeRemoved is only populated via calls from chunk unloading, clearing this list before entities get processed makes sense, and I don't see where this might cause other issues. I was always reluctant in moving stuff around and how they are executed within the tick, but this change makes absolute sense.

I tested it quite thoroughly, and seems like there is no hopper duping happening with this fix.

Timothy Miller 2017-08-04T19:39:20Z

In the process of testing this bug fix, I exposed another potentially serious and unrelated Minecraft bug.

Description in MC-119971

Timothy Miller 2017-08-04T22:19:50Z

One other thing. I think it may be better to move the "removeAll" code to much earlier. There are things that happen between queueing chunks to unload and deleting the tile entities that may cause other chunks to get reloaded that were just queued. If that happens, we may have the analogous bugs to what is causing the hopper problem.

The way I have it now is to delete the tileentity deletion code from World.updateEntities and move it into its own function in World:

public void removeUnloadedTileEntities()
{   
    if (!this.tileEntitiesToBeRemoved.isEmpty())
    {   
        this.tickableTileEntities.removeAll(this.tileEntitiesToBeRemoved);
        this.loadedTileEntityList.removeAll(this.tileEntitiesToBeRemoved);
        this.tileEntitiesToBeRemoved.clear();
    }
}

Then I insert a call to that RIGHT AFTER WorldServer.tick calls chunkProvider.unloadQueuedChunks, like this:

this.theProfiler.endStartSection("chunkSource");
    this.chunkProvider.unloadQueuedChunks();
    removeUnloadedTileEntities(); // new line

Soporan Paul 2017-08-05T19:41:46Z

Confirmed in 1.12.1

Timothy Miller 2017-09-14T13:45:00Z

I have not done a full analysis of the code between calling unloadQueuedChunks and doing removeAll. If the tile entities are removed right after being marked for removal as in my previous comment, then this is guaranteed safe with regard to tile entities.

If removeUnloadedTileEntities is called somewhere else, the thing we have to be careful about is with respect to other code in between unloadQueuedChunks and doing the removeAll. One thing in particular is ticking regular entities. Normally, they would not be ticked when unloaded chunks are nearby, but with multiple players, it's really easy to make chunk go directly from entity-processing to being unloaded, and this creates another opportunity for chunks to be unloaded and then reloaded on the same game tick. To be sure, the entity code deletes and ticks already in the right order. I'm just concerned about potential race conditions that haven't been fully ruled out. (Depending on what else is going on, we may want to delete regular entities earlier also!)

I was going to test these ideas, but MC-2025 got in my way. Although there have been fixes proposed earlier, I'm planning on doing a thorough analysis myself just to see if I can corroborate what others have said. Hopefully that will help add confidence to any community-proposed fixes. Either way, until 2025 is fixed, it's going to take some extra work for me to come up with a test case for regular entities and the interaction with loading and unloading, duping on chunk boundaries, MC-119971, etc.

Thanks!

pokechu22 2017-09-14T16:17:57Z

Marking as fixed for now. If something comes up with the entity code, let's create a new issue.

Timothy Miller 2017-09-14T17:22:50Z

Thanks @devs and @mods for getting this fixed!

We can now rely on hopper clocks not breaking, as long as they don't straddle a chunk boundary!!

However, if hopper pairs are put on a chunk boundary, it's still really easy to get them to dupe items, so we may want to think a little bit about whether or not the bug-as-originally-reported is really fixed, given that it's still possible to make hoppers dupe items. One of the causes is fixed by applying the fix attached to MC-79154 (which is a HUGE improvement, so thank you), but another cause isn't. The fix for the chunk boundary case is attached to MC-119971.

Long hopper lines for item delivery may still experience some problems, and pistons pushing blocks across chunk boundaries definitely will. Those are also fixed by the solution attached to MC-119971. In fact, the fix attached to MC-119971 is likely to also fix entity duplication and deletion that sometimes occurs at chunk boundaries. That fix is also being added to carpetmod so that community members can test it further.