[1.12.2] Constant Console Spam mekanism.common.tile.TileEntityQuantumEntangloporter<snip>removal without registration
Morpheus1101 opened this issue ยท 41 comments
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
@sfPlayer1 can you offer any help with this? As far as we can tell, we only register and de-register once
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.
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
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.
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.
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? ๐
IC2 has been made aware of the issue
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.
@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.
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.
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.
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)
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.
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
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
-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.
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...
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..
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]
So far im about half way through the list of coremods to determine which is the cause
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>
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.
Removing all the coremods appeared to alleviate the problem, that's why we think that ;)
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
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
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:?]
@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
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
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).
@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.
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 invalidate
s 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).