[Bug] Excessive Log Spam When Unable to Insert Into Inventory + TPS Loss
r-mc2 opened this issue · 8 comments
Mod Version
BotanyPots-1.16.5-7.0.2
Pack Used In
Enigmatica 6 v0.3.13
Issue
It would seem that whenever a hopper botany pot is unable to insert into the below inventory it issues a warning. All well and good, however, it does this each time the TE tries to tick. In the span of about 30 minutes I ended up with about 3,000,000 lines in my server's logs along the lines of:
[02Feb2021 23:30:23.403] [Server thread/WARN] [Bookshelf/]: A TileEntity with ID botanypots:botany_pot
at BlockPos{x=-35, y=68, z=105} in world ServerLevel[2020] failed a client update tick!
[02Feb2021 23:30:23.404] [Server thread/ERROR] [Bookshelf/CATCHING]: Catching
java.lang.NullPointerException: null
over and over again.
For reference I had the hopper botany pot sitting atop a BlockCarpentry's Illusion Chest masked with a grass block from Biome'o'Plenty's Origin Biome (it looked great btw) but apparently their chests don't accept items in whatever way the hopper pot tries to insert them (although I'd assume it's just like the name implies, a hopper).
There were 19 of these set up and with how fast the server was having to keep up with the log output the server suffered roughly a 15-20ms TPS loss (server average is around 40ms, with the logs going crazy we spiked upwards of 70ms). TPS was measured with /forge tps.
Please upload the full message being printed in your log, this is saying that there was a soft-crash for the pot and that an underlying error needs to be fixed. You cut it off just before it got to the part where it explains that error.
I can grab that for you in a couple hours when I'm back at the machine with RDP to the server, but I wasn't exaggerating with the 3,000,000 lines of log output. The GZipped log files were over 3MB in size each.
I think the very end of the last log has what you're looking for although I can't guarantee the full crash report will be there. The last thing the server was reporting was it was "preparing the crash-log" but hung on it. To the point that breaking blocks in-game was resulting in no blocks entities dropping, effectively like breaking a block in creative. I rebooted the server at that point.
But as I know how to reproduce it I could try letting it run again and see if I can cut it off just shy of the millions of lines 😆
So scouring the logs I found two that should be relevant although perhaps not as enlightening as we'd hope:
This is, near as I can tell, the error for when I was trying to clean up the BlockCarpentry Illusion Chests with Ultimine:
Click to show/hide Log
[03Feb2021 00:38:02.977] [Server thread/WARN] [Bookshelf/]: A TileEntity with ID botanypots:botany_pot at BlockPos{x=-30, y=69, z=106} in world ServerLevel[2020] failed a client update tick!
[03Feb2021 00:38:02.977] [Server thread/ERROR] [Bookshelf/CATCHING]: Catching
java.lang.NullPointerException: null
[03Feb2021 00:38:40.371] [Server thread/FATAL] [net.minecraftforge.common.ForgeMod/]: Preparing crash report with UUID
[03Feb2021 00:38:40.373] [Server thread/INFO] [STDOUT/]: [net.minecraft.crash.CrashReport:func_85057_a:196]: Negative index in crash report handler (0/36)
[03Feb2021 00:38:40.379] [Server thread/ERROR] [net.minecraftforge.eventbus.EventBus/EVENTBUS]: Exception caught during firing event: Exception while updating neighbours
Index: 23
Listeners:
...
23: ASM: com.feed_the_beast.mods.ftbultimine.FTBUltimine@2125a97b blockBroken(Lnet/minecraftforge/event/world/BlockEvent$BreakEvent;)V
...
net.minecraft.crash.ReportedException: Exception while updating neighbours
at net.minecraft.world.World.func_190524_a(World.java:351)
at net.minecraft.world.World.func_195593_d(World.java:296)
at net.minecraft.world.server.ServerWorld.func_230547_a_(ServerWorld.java:1372)
at net.minecraft.world.World.markAndNotifyBlock(World.java:236)
at net.minecraft.world.World.func_241211_a_(World.java:212)
at net.minecraft.world.World.func_180501_a(World.java:176)
at net.minecraftforge.common.extensions.IForgeBlock.removedByPlayer(IForgeBlock.java:197)
at net.minecraftforge.common.extensions.IForgeBlockState.removedByPlayer(IForgeBlockState.java:157)
at net.minecraft.server.management.PlayerInteractionManager.removeBlock(PlayerInteractionManager.java:271)
at net.minecraft.server.management.PlayerInteractionManager.func_180237_b(PlayerInteractionManager.java:254)
at com.feed_the_beast.mods.ftbultimine.FTBUltimine.blockBroken(FTBUltimine.java:176)
at net.minecraftforge.eventbus.ASMEventHandler_650_FTBUltimine_blockBroken_BreakEvent.invoke(.dynamic)
at net.minecraftforge.eventbus.ASMEventHandler.invoke(ASMEventHandler.java:85)
at net.minecraftforge.eventbus.EventBus.post(EventBus.java:302)
at net.minecraftforge.eventbus.EventBus.post(EventBus.java:283)
at net.minecraftforge.common.ForgeHooks.onBlockBreakEvent(ForgeHooks.java:581)
at net.minecraft.server.management.PlayerInteractionManager.func_180237_b(PlayerInteractionManager.java:230)
at net.minecraft.server.management.PlayerInteractionManager.func_229860_a_(PlayerInteractionManager.java:220)
at net.minecraft.server.management.PlayerInteractionManager.func_225416_a(PlayerInteractionManager.java:168)
at net.minecraft.network.play.ServerPlayNetHandler.func_147345_a(ServerPlayNetHandler.java:929)
at net.minecraft.network.play.client.CPlayerDiggingPacket.func_148833_a(SourceFile:40)
at net.minecraft.network.play.client.CPlayerDiggingPacket.func_148833_a(SourceFile:10)
at net.minecraft.network.PacketThreadUtil.func_225383_a(SourceFile:21)
at net.minecraft.util.concurrent.TickDelayedTask.run(SourceFile:18)
at net.minecraft.util.concurrent.ThreadTaskExecutor.func_213166_h(SourceFile:144)
at net.minecraft.util.concurrent.RecursiveEventLoop.func_213166_h(SourceFile:23)
at net.minecraft.server.MinecraftServer.func_213166_h(MinecraftServer.java:733)
at net.minecraft.server.MinecraftServer.func_213166_h(MinecraftServer.java:159)
at net.minecraft.util.concurrent.ThreadTaskExecutor.func_213168_p(SourceFile:118)
at net.minecraft.server.MinecraftServer.func_213205_aW(MinecraftServer.java:716)
at net.minecraft.server.MinecraftServer.func_213168_p(MinecraftServer.java:710)
at net.minecraft.util.concurrent.ThreadTaskExecutor.func_213160_bf(SourceFile:103)
at net.minecraft.server.MinecraftServer.func_213202_o(MinecraftServer.java:695)
at net.minecraft.server.MinecraftServer.func_240802_v_(MinecraftServer.java:645)
at net.minecraft.server.MinecraftServer.lambda$startServer$0(MinecraftServer.java:232)
at java.lang.Thread.run(Unknown Source)
Caused by: java.lang.NullPointerException
And this one I think is the one where it was trying to generate the crash report but wasn't fully able to with how overloaded the server became during the excessive logging:
Click to show/hide logs
[03Feb2021 00:36:11.215] [Server thread/FATAL] [net.minecraftforge.common.ForgeMod/]: Preparing crash report with UUID [03Feb2021 00:36:11.217] [Server thread/INFO] [STDOUT/]: [net.minecraft.crash.CrashReport:func_85057_a:196]: Negative index in crash report handler (0/29) [03Feb2021 00:36:11.220] [Server thread/FATAL] [net.minecraft.util.concurrent.ThreadTaskExecutor/]: Error executing task on Server net.minecraft.crash.ReportedException: Exception while updating neighbours at net.minecraft.world.World.func_190524_a(World.java:351) ~[?:?] at net.minecraft.world.World.func_195593_d(World.java:296) ~[?:?] at net.minecraft.world.server.ServerWorld.func_230547_a_(ServerWorld.java:1372) ~[?:?] at net.minecraft.world.World.markAndNotifyBlock(World.java:236) ~[?:?] at net.minecraft.world.World.func_241211_a_(World.java:212) ~[?:?] at net.minecraft.world.World.func_180501_a(World.java:176) ~[?:?] at net.minecraftforge.common.extensions.IForgeBlock.removedByPlayer(IForgeBlock.java:197) ~[forge:?] at net.minecraftforge.common.extensions.IForgeBlockState.removedByPlayer(IForgeBlockState.java:157) ~[forge:?] at net.minecraft.server.management.PlayerInteractionManager.removeBlock(PlayerInteractionManager.java:271) ~[?:?] at net.minecraft.server.management.PlayerInteractionManager.func_180237_b(PlayerInteractionManager.java:254) ~[?:?] at net.minecraft.server.management.PlayerInteractionManager.func_229860_a_(PlayerInteractionManager.java:220) ~[?:?] at net.minecraft.server.management.PlayerInteractionManager.func_225416_a(PlayerInteractionManager.java:190) ~[?:?] at net.minecraft.network.play.ServerPlayNetHandler.func_147345_a(ServerPlayNetHandler.java:929) ~[?:?] at net.minecraft.network.play.client.CPlayerDiggingPacket.func_148833_a(SourceFile:40) ~[?:?] at net.minecraft.network.play.client.CPlayerDiggingPacket.func_148833_a(SourceFile:10) ~[?:?] at net.minecraft.network.PacketThreadUtil.func_225383_a(SourceFile:21) ~[?:?] at net.minecraft.util.concurrent.TickDelayedTask.run(SourceFile:18) ~[?:?] at net.minecraft.util.concurrent.ThreadTaskExecutor.func_213166_h(SourceFile:144) ~[?:?] at net.minecraft.util.concurrent.RecursiveEventLoop.func_213166_h(SourceFile:23) ~[?:?] at net.minecraft.server.MinecraftServer.func_213166_h(MinecraftServer.java:733) ~[?:?] at net.minecraft.server.MinecraftServer.func_213166_h(MinecraftServer.java:159) ~[?:?] at net.minecraft.util.concurrent.ThreadTaskExecutor.func_213168_p(SourceFile:118) ~[?:?] at net.minecraft.server.MinecraftServer.func_213205_aW(MinecraftServer.java:716) ~[?:?] at net.minecraft.server.MinecraftServer.func_213168_p(MinecraftServer.java:710) ~[?:?] at net.minecraft.util.concurrent.ThreadTaskExecutor.func_213160_bf(SourceFile:103) ~[?:?] at net.minecraft.server.MinecraftServer.func_213202_o(MinecraftServer.java:695) ~[?:?] at net.minecraft.server.MinecraftServer.func_240802_v_(MinecraftServer.java:645) ~[?:?] at net.minecraft.server.MinecraftServer.lambda$startServer$0(MinecraftServer.java:232) ~[?:?] at java.lang.Thread.run(Unknown Source) [?:1.8.0_271] Caused by: java.lang.NullPointerException
Although this one also mentions CPlayerDiggingPacket so perhaps some interaction of trying to Ultimine up the problematic blocks while the crash reporter was trying to generate the report?
I just repeated it in a single player testing world and was able to capture a better log report:
Click to show/hide Logs
[Server thread/WARN]: A TileEntity with ID botanypots:botany_pot at BlockPos{x=108, y=5, z=-100} in world ServerLevel[Testing] failed a client update tick!
[Server thread/ERROR]: Catching
java.lang.NullPointerException: null
at mod.pianomanu.blockcarpentry.tileentity.ChestFrameTileEntity.getCapability(ChestFrameTileEntity.java:234) ~[?:1.16-0.3.5a]
at net.darkhax.bookshelf.util.InventoryUtils.getInventory(InventoryUtils.java:55) ~[?:10.0.1]
at net.darkhax.botanypots.block.tileentity.TileEntityBotanyPot.attemptAutoHarvest(TileEntityBotanyPot.java:310) ~[?:7.0.2]
at net.darkhax.botanypots.block.tileentity.TileEntityBotanyPot.onTileTick(TileEntityBotanyPot.java:271) ~[?:7.0.2]
at net.darkhax.bookshelf.block.tileentity.TileEntityBasicTickable.func_73660_a(TileEntityBasicTickable.java:27) [?:10.0.1]
at net.minecraft.world.World.func_217391_K(World.java:491) [?:?]
at net.minecraft.world.server.ServerWorld.func_72835_b(ServerWorld.java:371) [?:?]
at net.minecraft.server.MinecraftServer.func_71190_q(MinecraftServer.java:850) [?:?]
at net.minecraft.server.MinecraftServer.func_71217_p(MinecraftServer.java:786) [?:?]
at net.minecraft.server.integrated.IntegratedServer.func_71217_p(IntegratedServer.java:78) [?:?]
at net.minecraft.server.MinecraftServer.func_240802_v_(MinecraftServer.java:641) [?:?]
at net.minecraft.server.MinecraftServer.lambda$startServer$0(MinecraftServer.java:232) [?:?]
at net.minecraft.server.MinecraftServer$$Lambda$28835/758993816.run(Unknown Source) [?:?]
at java.lang.Thread.run(Thread.java:745) [?:1.8.0_51]
No idea why the server wasn't able to capture this as cleanly. Maybe something about having 19 ticking all at once. Also it looks like the NPE might be more on BlockCarpentry's side given the stack-trace, but is there anything to prevent the hopper from trying again if it gets an NPE? So it doesn't end up retrying until it fills up the logs.
For reference I left the testing flower in the pot for roughly 5 seconds and ended up with 4550 lines of log output warning me the botany pot ran into an issue interacting with the illusion chest.
P.S.
A quick screenshot of the server logs and why I wasn't able to give you the extra details in the original post:
Click to show/hide screenshot
And, yes, that is log lines 1.8 million and onwards 😄
Yes, this issue is completely unrelated to Botany Pots. BlockCarpentry is nullifying their own inventory reference and then trying to access it again later. Someone has already reported the same exception in a scenario using XNet pipes.
This type of issue would normally result in the game crashing, and the world being soft-locked as loading the chunks again would trigger the same crash. It can also result in world corruption under the right circumstances. My mod prevents the game from locking up and reports the issue in the logs instead. This is safer than the alternative, but you should still treat the issue like a normal server crash and not ignore/overlook it.
Thanks for getting back to me.
Totally understandable and I definitely appreciate taking precautions to help safeguard the world. Is there no way to limit how often the log messages get generated though? Protecting the chunk and server is great, but 4 million lines of log output in 30 minutes still seems like a level of excessive that could be trimmed back? Especially with how the logs alone nearly brought the server to its knees.
Or are you saying that the logs are only generating this much because of the error on BlockCarpentry's side?
The error is generated each time an instance of that error occurs. The only way to stop it would be to resolve the actual error. For example remove/update the broken mod, or go into the game and remove the broken block from the scenario that is causing the error.
Would it be possible to track when the last instance of the log was set to generate? Record that time and if it's been less than say 100ms or even 1000ms and is the same block coordinates skip the log? Safe to assume it is the same issue? I'm just thinking in terms of how long it may take someone to notice an error like this on a server or even single player without some log aggregator noticing the same error generating at a high rate.
I realize this is someone else's root error, but just a suggestion on helping to keep a cleaner log.