Mekanism

Mekanism

111M Downloads

[1.12.2] Constant Console Spam mekanism.common.tile.TileEntityQuantumEntangloporter<snip>removal without registration

Morpheus1101 opened this issue ยท 41 comments

commented

The below lines and ones identical but another machine are continually spammed on the server console, this relates to #4874 & #4955 All machines listed when it spams the message quite frequently, exist in the locations specified & majority of the entire base is powered from an Entangloporter

Forge v*.2.2625
IC2 v2.8.54-112
Mekanism v9.4.3.330

[19:28:21] [ic2-poolthread-1/WARN] [ic2.EnergyNet]: Tile mekanism.common.tile.TileEntityQuantumEntangloporter@76110a89 (dim 0: 2601/84/-1074) removal without registration

[19:28:21] [ic2-poolthread-1/WARN] [ic2.EnergyNet]: Tile mekanism.common.tile.TileEntityQuantumEntangloporter@54e0f1e (dim 0: 2625/77/-1054) removal without registration

commented

@sfPlayer1 can you offer any help with this? As far as we can tell, we only register and de-register once

https://github.com/aidancbrady/Mekanism/blob/master/src/main/java/mekanism/common/tile/prefab/TileEntityElectricBlock.java#L59

commented

The check is unsafe, IC2 doesn't process additions/removals immediately to work around various TE lifecycle issues. This should work without trickery on your side.

commented

i've noticed this occuring in server startup as well, not sure if it has any bearing on anything:

[18:55:42] [Server thread/INFO] [FML/]: The mod mekanism has attempted to allocate a chunkloading ticket beyond it's currently allocated maximum: 200

commented

hmm, how many mek blocks with Anchor upgrades do you have in that world?

commented

I couldnt even start to guess .. i know 1 base is practically completely powered by it, a handful of quarries and who knows how many other ppl r using them. If the mek pumps use them, then 200 would not even come close to to the amount id say.

commented

Seems like someone is spamming the upgrades (the miner/teleporter/entangloporter doesnt chunkload unless it has that updgrade)

Currently it uses generic per-mod tickets rather than per-user-profile tickets, so you'd have to increase the number in the forge config.

commented

Quite a lot of entangloporter's are being used

commented

Any further information on this at all?

commented

emmm has the same problem as that.
as far as I know, this problem might cause by chunk unload on server, I have installed mek with IC2 on a personal server with my friend, and the spam message was appeared while chunk, which contains mek blocks, was unloaded.
something seems like should be registed to removed while chunk unloading and registed to be active while chunk loading?
I'm not sure, is that the rule(or problem) of IC2? ๐Ÿ˜…

commented

IC2 has been made aware of the issue

https://bt.industrial-craft.net/view.php?id=2334

commented

whooops, hope fix that soon XD

commented

The immediate cause is most likely the linked Mekanism code, nothing in IC2. It's quite likely that the previous registration still hangs in IC2's queue if chunks get reloaded, so getTile doesn't reflect the addition yet. Coupling the ENet (de-)registrations to the TE lifecycle (onLoad, onChunkUnload, invalidate) should be all that's needed.

commented

Guess i'll just wait for an update at some point :D

commented

Still getting the spam using this version

commented

@sfPlayer1 the linked build in my post above only calls the register/deregister on lifecycle events (no special checks) yet Morpheus appears to still be getting the problem

And the issue was closed on your tracker with absolutely no useful comment.

commented

I don't know what exactly is wrong, more data is needed. As it is the code doesn't look wrong, but maybe I'm missing something or it changed on us. The TE lifecycle is unfortunately a major mess in MC and the general concept - reliably tracking TEs - is important enough to not just ignore the issue.

We have debug logging for this kind of issue available through the config (logEnetApiAccesses and logGridUpdatesVerbose), but it may be also required to log invocations of the TE methods (validate, invalidate, onChunkUnload) on Mekanism's side.

Maybe Mekanism can add the extra logging and Morpheus can grab a new log with it enabled? I am very interested in getting this bug squashed.

commented

I have a local copy of the server, so i can run a new instance with newer logs quite easily and happy to provide them.

commented

I got this issue aswell, and upon starting my server this spams the console:
15.04 14:29:22 [Server] Server thread/WARN [ic2.EnergyNet]: Tile mekanism.generators.common.tile.TileEntitySolarGenerator@4ab0cf9f (dim 2: 35/255/34) was unloaded in grid update (ADDITION)

commented

It's odd that it logs invalidate() invocations. MC calls invalidate only when a block was removed/replaced, not for chunk unloads.

The logging from Mekanism unfortunately doesn't contain the position, so I can't correlate it properly with other messages. Please add it, using the same format as IC2 to make ctrl+f work.

For IC2 the config setting debug/logEnetApiAccesses appears to be disabled. It logs right at the API edge, making issues easier to dissect.

commented

Yeah I realised that after I saw the log myself, I've since sent Morpheus a build that will include the instance identity code the same way ic2 displays it

commented

With the new code form thiakill and the config change in IC2, re-ran the server and the full outout log is @ https://gist.github.com/Morpheus1101/127d2c2242ba99954cc346d7894d82b6 (updated with current information)

Brief snippet is:

[17:17:18] [ic2-poolthread-1/WARN] [ic2.EnergyNet]: Tile mekanism.common.tile.TileEntityFactory@2ae554e (dim 0: -899/69/1238) removal without registration
[17:17:18] [ic2-poolthread-1/WARN] [ic2.EnergyNet]: Tile mekanism.common.tile.TileEntityFactory@79c81996 (dim 0: -899/69/1239) removal without registration
[17:17:18] [ic2-poolthread-1/WARN] [ic2.EnergyNet]: Tile mekanism.common.tile.TileEntityFactory@60c87a0 (dim 0: -899/69/1237) removal without registration
[17:18:03] [Server thread/INFO] [Mekanism]: TileEntityElectricBlock.onChunkUnload @8754598
[17:18:03] [Server thread/INFO] [Mekanism]: TileEntityElectricBlock.deregister @8754598
[17:18:03] [Server thread/INFO] [Mekanism]: TileEntityElectricBlock.onChunkUnload @12eb4722
[17:18:03] [Server thread/INFO] [Mekanism]: TileEntityElectricBlock.deregister @12eb4722
[17:18:03] [Server thread/INFO] [Mekanism]: TileEntityElectricBlock.onChunkUnload @4a41630
[17:18:03] [Server thread/INFO] [Mekanism]: TileEntityElectricBlock.deregister @4a41630
[17:18:03] [Server thread/INFO] [Mekanism]: TileEntityElectricBlock.onLoad @307b1ce0
[17:18:03] [Server thread/INFO] [Mekanism]: TileEntityElectricBlock.register @307b1ce0
[17:18:03] [Server thread/INFO] [Mekanism]: TileEntityElectricBlock.invalidate @307b1ce0
[17:18:03] [Server thread/INFO] [Mekanism]: TileEntityElectricBlock.deregister @307b1ce0
[17:18:03] [Server thread/INFO] [Mekanism]: TileEntityElectricBlock.onLoad @4f8a01bd
[17:18:03] [Server thread/INFO] [Mekanism]: TileEntityElectricBlock.register @4f8a01bd
[17:18:03] [Server thread/INFO] [Mekanism]: TileEntityElectricBlock.invalidate @4f8a01bd
[17:18:03] [Server thread/INFO] [Mekanism]: TileEntityElectricBlock.deregister @4f8a01bd
[17:18:03] [Server thread/INFO] [Mekanism]: TileEntityElectricBlock.onLoad @727af8e6
[17:18:03] [Server thread/INFO] [Mekanism]: TileEntityElectricBlock.register @727af8e6
[17:18:03] [Server thread/INFO] [Mekanism]: TileEntityElectricBlock.invalidate @727af8e6
[17:18:03] [Server thread/INFO] [Mekanism]: TileEntityElectricBlock.deregister @727af8e6
[17:18:03] [ic2-poolthread-2/WARN] [ic2.EnergyNet]: Tile mekanism.common.tile.TileEntityFactory@8754598 (dim 0: -899/69/1238) removal without registration
[17:18:03] [ic2-poolthread-2/WARN] [ic2.EnergyNet]: Tile mekanism.common.tile.TileEntityFactory@12eb4722 (dim 0: -899/69/1239) removal without registration
[17:18:03] [ic2-poolthread-2/WARN] [ic2.EnergyNet]: Tile mekanism.common.tile.TileEntityFactory@4a41630 (dim 0: -899/69/1237) removal without registration

commented

-899/69/1237 is a Basic Enriching Factory
-899/69/1239 is a Basic Smelting Factory
-899/69/1238 is a Basic Infusing factory

All of the machines are powered using DraconicEvolution as seen below by connecting a DE Wyvern Wierless Energy Crystal directly to the machines without using any sort of Conduits, pipes or anything else.

2018-04-22_17 09 38

commented

Something is definitely weird about your setup

[17:16:31] [Server thread/INFO] [Mekanism]: TileEntityElectricBlock.onLoad @2ae554e
[17:16:31] [Server thread/INFO] [Mekanism]: TileEntityElectricBlock.register @2ae554e
[17:16:31] [Server thread/INFO] [Mekanism]: TileEntityElectricBlock.invalidate @2ae554e

invalidate shouldnt be called less than 1 second after onLoad...

commented

Please also upload the matching debug.log (or fml-server-latest.log for old Forge), IC2 logs the API accesses with too low severity to show up in the regular log.

Assuming Mekanism does ENet unregistrations from invalidate, we may be able to obtain a stack trace by turning debug/logEnetApiAccessTraces on. Very curious what the cause is there..

commented

We're currently trying to work that out. Seems related to coremods unfortunately

[17:59:00] [Server thread/INFO] [Mekanism]: TileEntityElectricBlock.deregister @24b7ac97
[17:59:00] [Server thread/INFO] [Mekanism]: TileEntityElectricBlock.onLoad @40bcc7bb
[17:59:00] [Server thread/INFO] [Mekanism]: TileEntityElectricBlock.register @40bcc7bb
[17:59:00] [Server thread/INFO] [Mekanism]: TileEntityElectricBlock.invalidate @40bcc7bb
java.lang.Exception: null
        at mekanism.common.tile.prefab.TileEntityElectricBlock.func_145843_s(TileEntityElectricBlock.java:169) [TileEntityElectricBlock.class:?]
        at net.minecraft.world.chunk.Chunk.func_177426_a(Chunk.java:830) [axw.class:?]
        at net.minecraft.world.World.func_72939_s(World.java:1888) [amu.class:?]
        at net.minecraft.world.WorldServer.func_72939_s(WorldServer.java:613) [oo.class:?]
        at net.minecraft.server.MinecraftServer.func_71190_q(MinecraftServer.java:765) [MinecraftServer.class:?]
        at net.minecraft.server.dedicated.DedicatedServer.func_71190_q(DedicatedServer.java:396) [nz.class:?]
        at net.minecraft.server.MinecraftServer.func_71217_p(MinecraftServer.java:666) [MinecraftServer.class:?]
        at net.minecraft.server.MinecraftServer.run(MinecraftServer.java:524) [MinecraftServer.class:?]
        at java.lang.Thread.run(Unknown Source) [?:1.8.0_171]
commented

So far im about half way through the list of coremods to determine which is the cause

commented

Not necessarily/unlikely, the loop processing addedTileEntityList is probably doing this. The obvious question is why TEs with conflicting positions are in that list.

Deobf stack trace:

java.lang.Exception: null
        at mekanism.common.tile.prefab.TileEntityElectricBlock.invalidate(TileEntityElectricBlock.java:169) [TileEntityElectricBlock.class:?]
        at net.minecraft.world.chunk.Chunk.addTileEntity(Chunk.java:830) [axw.class:?]
        at net.minecraft.world.World.updateEntities(World.java:1888) [amu.class:?]
        at net.minecraft.world.WorldServer.updateEntities(WorldServer.java:613) [oo.class:?]
        at net.minecraft.server.MinecraftServer.updateTimeLightAndEntities(MinecraftServer.java:765) [MinecraftServer.class:?]
        at net.minecraft.server.dedicated.DedicatedServer.updateTimeLightAndEntities(DedicatedServer.java:396) [nz.class:?]
        at net.minecraft.server.MinecraftServer.tick(MinecraftServer.java:666) [MinecraftServer.class:?]
        at net.minecraft.server.MinecraftServer.run(MinecraftServer.java:524) [MinecraftServer.class:?]
        at java.lang.Thread.run(Unknown Source) [?:1.8.0_171]<input>
commented

It may be the best approach to inject a list wrapper (abstract list/collection delegating to what was there before) in addedTileEntityList that logs whenever it encounters a TE with one of the interesting positions.

commented

Removing all the coremods appeared to alleviate the problem, that's why we think that ;)

commented

Here is the log with the logging debug from thiakill's mekanism file

https://gist.github.com/Morpheus1101/127d2c2242ba99954cc346d7894d82b6

Basically you see a lot of this occuring:

[07:08:58] [ic2-poolthread-2/WARN] [ic2.EnergyNet]: Tile mekanism.common.tile.TileEntityFactory@75406943 (dim 0: -899/69/1238) removal without registration
[07:08:58] [ic2-poolthread-2/WARN] [ic2.EnergyNet]: Tile mekanism.common.tile.TileEntityFactory@69918b59 (dim 0: -899/69/1239) removal without registration
[07:08:58] [ic2-poolthread-2/WARN] [ic2.EnergyNet]: Tile mekanism.common.tile.TileEntityFactory@1649820e (dim 0: -899/69/1237) removal without registration
[07:09:42] [Server thread/INFO] [Mekanism]: TileEntityElectricBlock.onChunkUnload
[07:09:42] [Server thread/INFO] [Mekanism]: TileEntityElectricBlock.deregister
[07:09:42] [Server thread/INFO] [Mekanism]: TileEntityElectricBlock.onChunkUnload
[07:09:42] [Server thread/INFO] [Mekanism]: TileEntityElectricBlock.deregister
[07:09:42] [Server thread/INFO] [Mekanism]: TileEntityElectricBlock.onChunkUnload
[07:09:42] [Server thread/INFO] [Mekanism]: TileEntityElectricBlock.deregister
[07:09:42] [Server thread/INFO] [Mekanism]: TileEntityElectricBlock.onLoad
[07:09:42] [Server thread/INFO] [Mekanism]: TileEntityElectricBlock.register
[07:09:42] [Server thread/INFO] [Mekanism]: TileEntityElectricBlock.invalidate
[07:09:42] [Server thread/INFO] [Mekanism]: TileEntityElectricBlock.deregister
[07:09:42] [Server thread/INFO] [Mekanism]: TileEntityElectricBlock.onLoad
[07:09:42] [Server thread/INFO] [Mekanism]: TileEntityElectricBlock.register
[07:09:42] [Server thread/INFO] [Mekanism]: TileEntityElectricBlock.invalidate
[07:09:42] [Server thread/INFO] [Mekanism]: TileEntityElectricBlock.deregister
[07:09:42] [Server thread/INFO] [Mekanism]: TileEntityElectricBlock.onLoad
[07:09:42] [Server thread/INFO] [Mekanism]: TileEntityElectricBlock.register
[07:09:42] [Server thread/INFO] [Mekanism]: TileEntityElectricBlock.invalidate
[07:09:42] [Server thread/INFO] [Mekanism]: TileEntityElectricBlock.deregister
[07:09:42] [ic2-poolthread-3/WARN] [ic2.EnergyNet]: Tile mekanism.common.tile.TileEntityFactory@24df7bac (dim 0: -899/69/1238) removal without registration
[07:09:42] [ic2-poolthread-3/WARN] [ic2.EnergyNet]: Tile mekanism.common.tile.TileEntityFactory@6387ce2b (dim 0: -899/69/1239) removal without registration
[07:09:42] [ic2-poolthread-3/WARN] [ic2.EnergyNet]: Tile mekanism.common.tile.TileEntityFactory@652b22a2 (dim 0: -899/69/1237) removal without registration

commented

Traced it down with help from thiakill to be CompactMachines thats the cause, whilst the spam still occurs when the world 1st initially loads, subsequent spam does not occur

commented

In at least one case it appears to be a ghostloading issue caused by Draconic

at mekanism.common.tile.prefab.TileEntityElectricBlock.readFromNBT(TileEntityElectricBlock.java:182) [TileEntityElectricBlock.class:?]
at mekanism.common.tile.prefab.TileEntityMachine.readFromNBT(TileEntityMachine.java:158) [TileEntityMachine.class:?]
at mekanism.common.tile.TileEntityFactory.readFromNBT(TileEntityFactory.java:787) [TileEntityFactory.class:?]
at net.minecraft.tileentity.TileEntity.create(TileEntity.java:120) [avj.class:?]
at net.minecraft.world.chunk.storage.AnvilChunkLoader.loadEntities(AnvilChunkLoader.java:494) [aye.class:?]
at net.minecraftforge.common.chunkio.ChunkIOProvider.syncCallback(ChunkIOProvider.java:97) [ChunkIOProvider.class:?]
at net.minecraftforge.common.chunkio.ChunkIOExecutor.syncChunkLoad(ChunkIOExecutor.java:94) [ChunkIOExecutor.class:?]
at net.minecraft.world.gen.ChunkProviderServer.loadChunk(ChunkProviderServer.java:118) [on.class:?]
at net.minecraft.world.gen.ChunkProviderServer.loadChunk(ChunkProviderServer.java:89) [on.class:?]
at net.minecraft.world.gen.ChunkProviderServer.provideChunk(ChunkProviderServer.java:135) [on.class:?]
at net.minecraft.world.World.getChunkFromChunkCoords(World.java:309) [amu.class:?]
at net.minecraft.world.World.getChunkFromBlockCoords(World.java:304) [amu.class:?]
at net.minecraft.world.World.getTileEntity(World.java:2396) [amu.class:?]
at com.brandon3055.draconicevolution.blocks.energynet.tileentity.TileCrystalBase.balanceLinkedDevices(TileCrystalBase.java:120) [TileCrystalBase.class:?]
at com.brandon3055.draconicevolution.blocks.energynet.tileentity.TileCrystalBase.update(TileCrystalBase.java:93) [TileCrystalBase.class:?]
at com.brandon3055.draconicevolution.blocks.energynet.tileentity.TileCrystalDirectIO.update(TileCrystalDirectIO.java:42) [TileCrystalDirectIO.class:?]
at net.minecraft.world.World.updateEntities(World.java:1832) [amu.class:?]
at net.minecraft.world.WorldServer.updateEntities(WorldServer.java:613) [oo.class:?]
at net.minecraft.server.MinecraftServer.updateTimeLightAndEntities(MinecraftServer.java:765) [MinecraftServer.class:?]
at net.minecraft.server.dedicated.DedicatedServer.updateTimeLightAndEntities(DedicatedServer.java:396) [nz.class:?]
at net.minecraft.server.MinecraftServer.tick(MinecraftServer.java:666) [MinecraftServer.class:?]
at net.minecraft.server.MinecraftServer.run(MinecraftServer.java:524) [MinecraftServer.class:?]
commented

@sfPlayer1 so the IC2 error message seems to appear when the TE that was registered no longer exists. In this case the ic2 remove event is being fired from invalidate, and onChunkUnload does not appear to be being called.

Using on a chunkloader on the affected position reportedly solved it

commented

I don't have Compactmachines or Draconic and i get the error on both the initial world load and whenever an area with those problematic machines is loaded

commented

TileEntity.invalidate() should never get invoked unless the block was actually mined up (very unusual deliberate corner cases aside). invalidate is not the direct opposite of validate, the pair is really validate vs (invalidate XOR onChunkUnload).

commented

@tomthehero Any mod can trigger the edge case.

To all with this problem: It would appear we have solved the underlying issue, and it will be in the next release. When that is I cannot say. In the meantime, you will need to use a chunkloader on the affected positions.

commented

I think I've worked it out, and is potentially a Forge caused bug.

Forge sets net.minecraft.world.World#processingLoadedTiles to true before ticking TEs starts, so if a chunk is loaded by a ticking TE, the TEs that get added to the world by the chunk/chunkProvider go into the addedTileEntityList list and then processed further down.

During that processing it gets sent back to the Chunk's addTileEntity which sees that there is already a TE there, and so invalidates it (as there seems to be no instance check).

It does then validate() it though. So I guess we could do the IC2 message there instead of onLoad.

All the stacktraces Morpheus have shown me that Mek's calls to IC2 eNet registration are balanced out with de-registration however, so I'm stumped as to why IC2 is complaining (I'm sure I remember seeing code that handled a pending reg being cancelled).

commented

It would be great if mekanism changelogs were available

commented

The next release will have a proper changelog in curse ;)

commented

Thanks to all for workin on this and after a long effort an debugging, knocked this one off the bug list, much appreciated