Applied Energistics 2

Applied Energistics 2

137M Downloads

(Fabric) Items do not appear if you close and open terminal again

brenodantas10 opened this issue · 26 comments

commented

Describe the bug

Items and Recipes inside the ME network doesn't appear on the terminal but data is being occupied in Storage Cell as it should.

To Reproduce

  1. Set up a simple ME system with a ME Drive with a storage cell and a Terminal
  2. Open the terminal and put any item in the system (the item will appear properly)
  3. Close the terminal and re-open it, the item is not there anymore.
    (this happens with an ME Chest too and ME Interface recipes).

Expected behavior

Items and craftings showing properly in the terminal

Additional context

I don't think there's something significant in the logs, but a couple of warning and models some models not loaded
latest.log

Environment

  • Game Setup:

    • MultiMC
    • Fabric Loader 0.11.6
    • Fabric API 0.36.0+1.16 (the same things occurs with API version 0.34.7+1.16)
    • Applied Energistics 2 8.4.0-alpha.1
  • Environment:

    • Ubuntu 20.04.2 LTS
    • Intel® Core™ i7-6500U CPU @ 2.50GHz × 4
    • Mesa Intel® HD Graphics 520 (SKL GT2)
commented

I just want to note that this is only an issue in 8.4.0. Using 8.3.0-alpha.3 works fine, so for an immediate solution you can always downgrade.

commented

I just want to note that this is only an issue in 8.4.0. Using 8.3.0-alpha.3 works fine, so for an immediate solution you can always downgrade.

The only issue with using 8.3.0 alpha 3 is that it crashes with latest fabric api due to biomeAcessor changes, so we're stuck until a fix is discovered.

commented

Also, I can reproduce this using ONLY Applied 8.4.0 alpha 1 + Fabric API 0.37.1. Items go in, but after closing and reopening the terminal, the items are gone. no log messages, no errors, NOTHING.

Deposit items
image
Close and reopen
image

I've disabled ALL my mods and created a new world. ONLY Fabric API + AE2.
image

Something happened and we don't know what happened, because there are no log entries.

commented

I got the same issue while trying to update ae2wtlib
and I thought I broke something...
good to know this isn't my fault

commented

I would be very glad if this problem could be resolved very soon...

commented

Same happening here. I lost some items because of that.

commented

Same happening here. I lost some items because of that.

they shouldn't be lost, they should still be on the drives, they are just not accesible with the terminal

commented

That was fast! 😄
Gonna have a look at the solution too.

commented

Server might still be affected. Haven't started a new world to verify this, but copying an affected world to singleplayer seems to resolve in single player, while our current multiplayer world is still affected. Have tried pulling up drives and controllers as well as restarting and loading to singleplayer for cache clear operation on the world.

commented

Way too long of a post incoming, brace yourselves 😄

Observations

We ran into this issue after updating our server and I found that items sometimes show, but very rarely.
This made me think this has to be some kind of threading issue like a race condition.

After going through half the changes of the last merge commit and debugging what I found suspicious I landed here:

Container currentContainer = player.openContainer;
if (!(currentContainer instanceof MEMonitorableContainer)) {
// Ignore a packet for a screen that has already been closed
return null;
}

This returns null when I believe it shouldn't, here's a debug log:

[Netty Local Client IO #0/DEBUG]: called from MEInventoryUpdatePacket():
[Netty Local Client IO #0/DEBUG]: currentContainer = net.minecraft.class_1723@5979e729
[Netty Local Client IO #0/DEBUG]: returning null!
[main/DEBUG]: called from clientPacketData():
[main/DEBUG]: currentContainer = appeng.container.me.items.CraftingTermContainer@14fd921c

(class_1723 is PlayerScreenHandler in yarn which I believe is simply Container in MCP)

When interacting with the UI (putting an item inside the system, taking it out again), the log looks like this:

[Netty Local Client IO #0/DEBUG] [DEBUG]: called from MEInventoryUpdatePacket():
[Netty Local Client IO #0/DEBUG] [DEBUG]: currentContainer = appeng.container.me.items.CraftingTermContainer@207c1a23
[main/DEBUG] [DEBUG]: called from clientPacketData():
[main/DEBUG] [DEBUG]: currentContainer = appeng.container.me.items.CraftingTermContainer@207c1a23

Here, everything works.

Verification

getContainer() is used on the networking thread here:

MEMonitorableContainer<T> container = getContainer();
if (container != null) {
IStorageChannel<T> storageChannel = container.getStorageChannel();
for (int i = 0; i < itemCount; i++) {
this.list.add(GridInventoryEntry.read(storageChannel, data));
}
}

Removing the getContainer() and if, making ItemStorageChannel public and setting
storageChannel = new ApiStorage.ItemStorageChannel();
does indeed "fix" the issue.

Forge?

Since the code for Forge and Fabric looks identical in this place, Forge should also be affected by this.
I haven't tested this though.

Possible Explanation

The sequence of events in the first case is probably this:

  • the player right-clicks the terminal
  • a package is sent to the server
  • the server sees the player wants to open the container
  • the server sends a container/screen change packet
  • the server sends a MEInventoryUpdatePacket immediately afterwards
  • client receives the first packet and changes the container/screen
  • client receives the second packet and the networking thread runs forementioned code

It is quite clear that getContainer() is not thread-safe, as mentioned in this comment as well:

// This is slightly dangerous since it accesses the game thread from the network thread,
// but reading the current container is atomic (reference field), and from then the window id
// and storage channel are immutable.

Very little time elapses between changing the container (on the main thread) and accessing the container (on the networking thread, by running getContainer()), chances for it not being "naturally" synchronized is very high, that's why the code fails most the time.

Possible Solution

Looking at

MEMonitorableContainer<T> container = getContainer();
if (container != null) {
IStorageChannel<T> storageChannel = container.getStorageChannel();
for (int i = 0; i < itemCount; i++) {
this.list.add(GridInventoryEntry.read(storageChannel, data));
}
}

again, we see that the packet is parsed differently depending on the container's storage channel - we don't actually need to container itself.
The issue is that the packet needs to be parsed on the networking thread while getContainer() needs to run on the main thread.

While it's possible to "run" (enque) a task on the main thread like

Minecraft.getInstance().execute(() -> { ... something something `getContainer()` ... })

and it's also possible to block the network thread and wait for the answer, this will probably just produce a dead lock.

Maybe I'm wrong, but it feel like it should be possible to send the storage channel with the MEInventoryUpdatePacket packet data, since the server should already know what container was opened. That way getContainer() doesn't have to be called at all and we don't have any threading issues.

All (two) implementations of IStorageChannel have no state and can therefore easily be de/serialized, maybe by giving each a unique Identifier / a ResourceLocation.

commented

Extremely detailed post! Excellent to see some potential root-cause analysis on this.

I've identified a partial in-game workaround, where slapping an ME Toggle Bus down on the fluix cable against the isolated ME Drive array lets me turn off the storage, turn on the storage, and open the terminal before it powers on. It's not consistent after a few seconds, but usually long enough to at least get and send items. Queueing jobs to the crafting computer or snagging REI recipes for the Pattern Terminal usually is too slow for this workaround to help, though.

commented

Many thanks @Fourmisain for putting us on the right track to fix this.

commented

Does it work if you update the client? (Updating the server shouldn't make any difference)

commented

Yep, both client and server are updated. Singleplayer loads of the backup seem to function normally, and server exhibits issue even with only myself connected. Old version is removed from the folder as well.

The following setup with a toggle bus allows me to disconnect and reconnect the ME drive, opening the crafting terminal before the drive is online. This grants a few seconds of normal behavior. Reconnecting or rebooting the server also grant brief normal operation. Import/Export busses and craft job submission also will be affected when the storage is in this state, and resume functionality after the drive reconnection.

image

commented

If this is the same issue, it should log the following message in your client log:

Ignoring ME inventory update packet because the target menu isn't open.

commented

If this is the same issue, it should log the following message in your client log:

Ignoring ME inventory update packet because the target menu isn't open.

Yep. Verified all clients are connecting with the latest alpha2 and no older versions in the mods folder. Seems fine when server starts up, but after about 5 mins the issue returns. Attached is a video of this behavior and the workaround.

Having trouble replicating this on a server in creative, same versions of AE2, Fabric, Fabric API, REI, and Cloth. Working now on a duplicate server and reducing modlist by half each time to try and discern cause; potentially this is related to ATF3 instead of AE2, in which case I apologize for pestering further :) Hopefully will find out soon.

image
image

2021-08-08_14-13-30.mp4
commented

There are three reasons for why it may nott find the ME GUI, all three have the same log message.
I'll make the log messages distinct so we may figure out what is going on here...

The basic premise is:

  1. Server sends Packet to Client "Open GUI ME Terminal please"
  2. Server sends Packet to Client "Here's the Content of ME Terminal"
  3. Client receives and reads Packet 1
  4. Client processes Packet 1 (this opens the ME GUI)
  5. Client receives and reads Packet 2
  6. Client processes Packet 2 (this fills the ME GUI with content)

In general, 5 and 4 can be swapped, which was the bug we fixed (if the GUI isn't already open by the time the terminal content arrive on your client, the content gets discarded, now that's handled correctly).

The log message means that in step 6, the currently opened GUI is no longer recognized as the ME Terminal GUI that the server opened. It's possible something is interfering with it, but I am very sure that step 4 happens before step 6, otherwise a lot of other shit would be broken :-|

commented

@Xechorizo Can you please check with the jar from the attachment of this build? https://github.com/AppliedEnergistics/Applied-Energistics-2/actions/runs/1112501256

The only change is that there are different log-messages depending on why the inventory content gets dropped.
My personal hunch is that there's a client-side mod messing with the container, but we'll see.

commented

@shartte Using this extended logging build on both client and server, I've seen very little additional log messages, which indicates it's likely no longer this issue, as the symptoms have not appeared after noticing the discovery to follow. Here are the only two messages that arrived. Interestingly, they are precisely 30m apart. A (maybe) small recommendation would be to prefix all logs from AE2 with a tag of some kind ('[AE2] /message/', etc.):

[12:30:37] [main/INFO]: Loaded 1358 advancements
[12:47:32] [main/INFO]: Ignoring ME inventory update since the current container is now: net.minecraft.class_1723@61f7c26f
[13:00:30] [main/INFO]: [CHAT] [Textile Backup] Warning! Server backup will begin shortly. You may experience some lag.
[13:17:32] [main/INFO]: Ignoring ME inventory update since the current container is now: net.minecraft.class_1723@61f7c26f

I've also found the server behaves normally up until a recipe is added to a crafting terminal using REI 5.12.248. Still very difficult to replicate single-player with minimal mods outside of AoF3 pack, so there is likely either a mod interaction or something unrelated to this issue. Sadly, this is the latest build of REI for 1.16.5, so I will try to replicate further using only these mods, and continue the process of elimination with the pack as a whole.

Thank you again for all your help! I'll open a new issue if I'm able to gather anything more concrete.

commented

Hm. I checked what class_1723 is, that is just "no container"; essentially.
This in theory could happen if the screen is opened and immediately closed again by something (?)

commented

class_1723 is PlayerScreenHandler (aka PlayerContainer).

A (maybe) small recommendation would be to prefix all logs from AE2 with a tag of some kind ('[AE2] /message/', etc.):

Most logs are already prefixed, but it doesn't show in production (only in dev). This is probably something that can be changed in the log4j config, although I don't know how exactly. Would be good to have indeed.

commented

My symptoms likely correspond to #4839

commented

I'm having the same issue. I upgraded from 8.3.0 Alpha 3 (everything shows up) to 8.4.0 Alpha 1 (all gone.) You can put new items into the system and they show up, but once you close and reopen the terminal, those disappear as well. The portable cells have the same issue. All storage cells show the data as being used. Patterns in the interface terminal show up as intended but won't show up as craftable in the Crafting terminals.

My game setup is essentially the same as the OP's. I am also using AOF III, but customized and updated as the pack's mods are updated.

commented

Just throwing in a wild card here. Are you also using Conjuring (also in AOF3)? Removed my setup and restarted the game.. now things seem to work a bit better. Also did som other stuff so it not a total rule out but a candidate.

commented

My setup is just the what I've already mentioned

commented

No, sir... I tend to do a lot of pruning and updating when I use modpacks. Conjuring didn't make the cut.