Strange server behavior and crashes.
NoxyNixie opened this issue ยท 10 comments
We've been experiencing strange behavior with the mod on our server. For the most part it seems to work fine when you start a new Redstone Control build but after the chunk has unloaded (server restart, people moving away from that chunk, or people logging off) the data of the blocks seem to be potentially invalid or forgotten (I'm not sure what is happening)?
The first indication of something wrong in our log is the following:
[16:10:15] [Server thread/WARN] [rs_ctr API]: It appears the used up Signal Link IDs info wasn't properly saved to disk. IDs may have been assigned duplicate!
[16:10:15] [Server thread/WARN] [rs_ctr API]: It appears the used up Signal Link IDs info wasn't properly saved to disk. IDs may have been assigned duplicate!
[16:10:53] [Server thread/FATAL] [cd4017be_lib]: invalid TileEntity state: chunk = null, unloaded = true, world = net.minecraft.world.WorldServer@3f96d007, pos = BlockPos{x=540, y=85, z=217}
Where the last line is the person breaking and replacing the block that is behaving strangely (I think the error happens on breaking of the block).
This strange behavior also applies to the Processor Assembly and Circuit Designer which on the client when opening the interface immediately closes the interface again until you break and replace those blocks.
On one particular frustrating experience the server actually barked a bit more that just the three lines above:
[16:27:34] [Server thread/FATAL] [VanillaFix]: Error executing task
java.util.concurrent.ExecutionException: java.lang.NullPointerException
at java.util.concurrent.FutureTask.report(FutureTask.java:122) ~[?:1.8.0_252]
at java.util.concurrent.FutureTask.get(FutureTask.java:192) ~[?:1.8.0_252]
at net.minecraft.util.Util.runTask(SourceFile:531) [h.class:?]
at net.minecraft.server.MinecraftServer.updateTimeLightAndEntities(MinecraftServer.java:723) [MinecraftServer.class:?]
at net.minecraft.server.dedicated.DedicatedServer.updateTimeLightAndEntities(DedicatedServer.java:397) [nz.class:?]
at net.minecraft.server.MinecraftServer.tick(MinecraftServer.java:668) [MinecraftServer.class:?]
at net.minecraft.server.MinecraftServer.run(MinecraftServer.java:526) [MinecraftServer.class:?]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_252]
Caused by: java.lang.NullPointerException
at cd4017be.rs_ctr.port.SplitPlug.onPortModified(SplitPlug.java:195) ~[SplitPlug.class:?]
at cd4017be.api.rs_ctr.port.Link.<init>(Link.java:96) ~[Link.class:?]
at cd4017be.api.rs_ctr.port.Port.connect(Port.java:76) ~[Port.class:?]
at cd4017be.rs_ctr.port.WireBranch.addLink(WireBranch.java:167) ~[WireBranch.class:?]
at cd4017be.rs_ctr.port.SplitPlug.addLink(SplitPlug.java:175) ~[SplitPlug.class:?]
at cd4017be.rs_ctr.item.ItemWireCon.doAttach(ItemWireCon.java:102) ~[ItemWireCon.class:?]
at cd4017be.api.rs_ctr.port.MountedPort.onInteract(MountedPort.java:114) ~[MountedPort.class:?]
at cd4017be.rs_ctr.tileentity.Gate.onActivated(Gate.java:110) ~[Gate.class:?]
at cd4017be.lib.block.AdvancedBlock.onBlockActivated(AdvancedBlock.java:217) ~[AdvancedBlock.class:?]
at net.minecraft.server.management.PlayerInteractionManager.processRightClickBlock(PlayerInteractionManager.java:449) ~[or.class:?]
at net.minecraft.network.NetHandlerPlayServer.processTryUseItemOnBlock(NetHandlerPlayServer.java:741) ~[pa.class:?]
at net.minecraft.network.play.client.CPacketPlayerTryUseItemOnBlock.processPacket(SourceFile:55) ~[ma.class:?]
at net.minecraft.network.play.client.CPacketPlayerTryUseItemOnBlock.processPacket(SourceFile:11) ~[ma.class:?]
at net.minecraft.network.PacketThreadUtil$1.run(SourceFile:13) ~[hv$1.class:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[?:1.8.0_252]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[?:1.8.0_252]
at net.minecraft.util.Util.runTask(SourceFile:529) ~[h.class:?]
... 5 more
[16:27:37] [Server thread/FATAL] [VanillaFix]: Error executing task
java.util.concurrent.ExecutionException: java.lang.NullPointerException
at java.util.concurrent.FutureTask.report(FutureTask.java:122) ~[?:1.8.0_252]
at java.util.concurrent.FutureTask.get(FutureTask.java:192) ~[?:1.8.0_252]
at net.minecraft.util.Util.runTask(SourceFile:531) [h.class:?]
at net.minecraft.server.MinecraftServer.updateTimeLightAndEntities(MinecraftServer.java:723) [MinecraftServer.class:?]
at net.minecraft.server.dedicated.DedicatedServer.updateTimeLightAndEntities(DedicatedServer.java:397) [nz.class:?]
at net.minecraft.server.MinecraftServer.tick(MinecraftServer.java:668) [MinecraftServer.class:?]
at net.minecraft.server.MinecraftServer.run(MinecraftServer.java:526) [MinecraftServer.class:?]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_252]
Caused by: java.lang.NullPointerException
at cd4017be.rs_ctr.port.WireBranch.addLink(WireBranch.java:168) ~[WireBranch.class:?]
at cd4017be.rs_ctr.port.SplitPlug.addLink(SplitPlug.java:175) ~[SplitPlug.class:?]
at cd4017be.rs_ctr.port.SplitPlug.addLink(SplitPlug.java:180) ~[SplitPlug.class:?]
at cd4017be.rs_ctr.item.ItemWireCon.doAttach(ItemWireCon.java:102) ~[ItemWireCon.class:?]
at cd4017be.api.rs_ctr.wire.IWiredConnector$IWiredConnectorItem.doAttach(IWiredConnector.java:88) ~[IWiredConnector$IWiredConnectorItem.class:?]
at cd4017be.api.rs_ctr.wire.RelayPort.onInteract(RelayPort.java:89) ~[RelayPort.class:?]
at cd4017be.rs_ctr.tileentity.Gate.onActivated(Gate.java:110) ~[Gate.class:?]
at cd4017be.lib.block.AdvancedBlock.onBlockActivated(AdvancedBlock.java:217) ~[AdvancedBlock.class:?]
at net.minecraft.server.management.PlayerInteractionManager.processRightClickBlock(PlayerInteractionManager.java:449) ~[or.class:?]
at net.minecraft.network.NetHandlerPlayServer.processTryUseItemOnBlock(NetHandlerPlayServer.java:741) ~[pa.class:?]
at net.minecraft.network.play.client.CPacketPlayerTryUseItemOnBlock.processPacket(SourceFile:55) ~[ma.class:?]
at net.minecraft.network.play.client.CPacketPlayerTryUseItemOnBlock.processPacket(SourceFile:11) ~[ma.class:?]
at net.minecraft.network.PacketThreadUtil$1.run(SourceFile:13) ~[hv$1.class:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[?:1.8.0_252]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[?:1.8.0_252]
at net.minecraft.util.Util.runTask(SourceFile:529) ~[h.class:?]
... 5 more
[16:27:40] [Server thread/FATAL] [VanillaFix]: Error executing task
java.util.concurrent.ExecutionException: java.lang.NullPointerException
at java.util.concurrent.FutureTask.report(FutureTask.java:122) ~[?:1.8.0_252]
at java.util.concurrent.FutureTask.get(FutureTask.java:192) ~[?:1.8.0_252]
at net.minecraft.util.Util.runTask(SourceFile:531) [h.class:?]
at net.minecraft.server.MinecraftServer.updateTimeLightAndEntities(MinecraftServer.java:723) [MinecraftServer.class:?]
at net.minecraft.server.dedicated.DedicatedServer.updateTimeLightAndEntities(DedicatedServer.java:397) [nz.class:?]
at net.minecraft.server.MinecraftServer.tick(MinecraftServer.java:668) [MinecraftServer.class:?]
at net.minecraft.server.MinecraftServer.run(MinecraftServer.java:526) [MinecraftServer.class:?]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_252]
Caused by: java.lang.NullPointerException
at cd4017be.rs_ctr.port.SplitPlug.onPortModified(SplitPlug.java:195) ~[SplitPlug.class:?]
at cd4017be.api.rs_ctr.port.Link.<init>(Link.java:96) ~[Link.class:?]
at cd4017be.api.rs_ctr.port.Port.connect(Port.java:76) ~[Port.class:?]
at cd4017be.rs_ctr.port.WireBranch.addLink(WireBranch.java:167) ~[WireBranch.class:?]
at cd4017be.rs_ctr.port.SplitPlug.addLink(SplitPlug.java:175) ~[SplitPlug.class:?]
at cd4017be.rs_ctr.port.SplitPlug.addLink(SplitPlug.java:180) ~[SplitPlug.class:?]
at cd4017be.rs_ctr.item.ItemWireCon.doAttach(ItemWireCon.java:102) ~[ItemWireCon.class:?]
at cd4017be.api.rs_ctr.port.MountedPort.onInteract(MountedPort.java:114) ~[MountedPort.class:?]
at cd4017be.rs_ctr.tileentity.Gate.onActivated(Gate.java:110) ~[Gate.class:?]
at cd4017be.lib.block.AdvancedBlock.onBlockActivated(AdvancedBlock.java:217) ~[AdvancedBlock.class:?]
at net.minecraft.server.management.PlayerInteractionManager.processRightClickBlock(PlayerInteractionManager.java:449) ~[or.class:?]
at net.minecraft.network.NetHandlerPlayServer.processTryUseItemOnBlock(NetHandlerPlayServer.java:741) ~[pa.class:?]
at net.minecraft.network.play.client.CPacketPlayerTryUseItemOnBlock.processPacket(SourceFile:55) ~[ma.class:?]
at net.minecraft.network.play.client.CPacketPlayerTryUseItemOnBlock.processPacket(SourceFile:11) ~[ma.class:?]
at net.minecraft.network.PacketThreadUtil$1.run(SourceFile:13) ~[hv$1.class:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[?:1.8.0_252]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[?:1.8.0_252]
at net.minecraft.util.Util.runTask(SourceFile:529) ~[h.class:?]
... 5 more
This was during an attempted fixing of the strangely broken Redstone Control build. During this rebuild the client (JennyLeeP) also crashed with the following crash (multiple times):
After a bit of fiddling later the client (JennyLeeP) had to go for a minute and logged off. About a minute later after she logged back on the server crashed with the following crash:
I'm not sure if this all is related to a single issue or multiple problems. Hope you can fix these as currently the mod seems unusable on our server.
So, now I got the Signal Link ID file to save alongside the regular world save whenever there were new connections added (previously it would only save during server shutdown). This should fix ID collisions in the future.
I figured out that the new crash was indirectly caused by the Link ID collision as well, so I additionally improved the way these collisions are handled to prevent such crashes.
Haven't made much progress with the invalid TileEntity thing except adding more debug logging. The problem is that I can't reproduce it in my dev environment or my test mod packs. According to your logs it happens only rarely. The circuit designer being affected confirms that it caused GUI insta-close issue, I made a workaround fix for that.
New updates:
CD4017BE_lib
RedstoneControl
I have the same problem with CD4017BE_lib-1.12.2-6.5.1.jar and RedstoneControl-1.12.2-0.3.1.3.jar:
start a new Redstone Control build but after the chunk has unloaded (server restart, people moving away from that chunk, or people logging off) the data of the blocks seem to be potentially invalid or forgotten (I'm not sure what is happening)?
I can not click on any buttons and levers on panels. It happens every day.
This is the full server log of the events described above:
I've just compiled a mod update that mainly adds a Block Teleporter and some utility features. But alongside my efforts to make everything in the mod compatible with being teleported around, I also rewrote code related to the errors and crashes you had and they shouldn't happen anymore.
You can download it here and the required library version here (the topmost .jar file under Assets). I may later add a beta release on curse forge as well.
You should backup your world because the save data structure for wire connections changed, so once blocks are loaded in that version, you can't go back anymore without breaking everything. Also old connections from before the update will behave a bit strange when removing them.
Issues that are probably not fixed yet are:
Signal Link IDs: might be related to world backups that don't catch the file because it's saved at the wrong time or caused when the server stops in an unusual way. The consequences of this issue are buggy wire connections in case new wires are placed and they get assigned the same IDs as some existing ones.invalid TileEntity state: It appears that TileEntities are sometimes not initialized correctly from chunk load. I haven'd yet figured out why but added some debug code that prints this message whenever it happens and attempts to correct the invalid state which would otherwise lead to a crash. This might have caused the closing GUI issue. It would be nice to know what the blocks at{x=29, y=63, z=-2229}and{x=540, y=85, z=217}were and whether they had buggy behavior afterwards.
So far ... well ... things didn't go too well. JennyLeeP was rebuilding here stuff as expected it would be broken but hopefully fixed after she rebuild everything (once again).
She left for a little bit and while I tried to rejoin the server after a little bit away it decided to immediately crash with the following crashlog:
The server log has all kinds of interesting lines such as:
[22:03:45] [Server thread/FATAL] [cd4017be_lib]: invalid TileEntity state: chunk = null, unloaded = true, world = net.minecraft.world.WorldServer@318b65e9, pos = BlockPos{x=21, y=63, z=-2229}
But these were during the rebuilding.
A second or two after my client connects the shit hits the fan and various things are barked in the console. I'm not sure what to make of the info
Here is the full log: latest.log
I'm not sure if JennyLeeP rebuild everything or just parts of her build.
The block in question {x=29, y=63, z=-2229} that Noxy is referencing at my base was a control panel.
The panel had 1 switch , 3 lamps, 1 slider , and a 1x4 text module.
I have rebuilt all 4 systems multiple time snow and I can confirm that the issues have not been resolved.
Most of the issues I have witnessed so far happen on chunk unload.
Deactivating the force chunk loading in forge prevented the game from crashing instantly
Signal Link IDs: might be related to world backups that don't catch the file because it's saved at the wrong time or caused when the server stops in an unusual way. The consequences of this issue are buggy wire connections in case new wires are placed and they get assigned the same IDs as some existing ones.
Our backup mechanism is pretty much the standard for minecraft servers. We ensure that minecraft isn't saving to its files, then we copy the files and afterwards we enable the saving. This way we don't copy files that are being written to at the same time causing corruption. If your mod is writing to files while the server saving is disabled this may cause corrupted backups however we have not rolled back to a backup since we added your mod so even if those files were corrupted during the backup copy phase this should not affect the live server.
In case you are curious this is our backup script: https://pastebin.com/6Rb5n99C
invalid TileEntity state: It appears that TileEntities are sometimes not initialized correctly from chunk load. I haven'd yet figured out why but added some debug code that prints this message whenever it happens and attempts to correct the invalid state which would otherwise lead to a crash. This might have caused the closing GUI issue. It would be nice to know what the blocks at{x=29, y=63, z=-2229}and{x=540, y=85, z=217}were and whether they had buggy behavior afterwards.
The block at {x=540, y=85, z=217}: 
(I may have placed the assembler and designer the other way around when I placed them back).
I'm not sure what was at {x=29, y=63, z=-2229} as that is JennyLeeP's base and currently its just a standard block at that location:
I'll have to ask her when she gets back what was at that location.
You can download it here and the required library version here
Done, downloaded and updated; Seems to work so far, however at this time I have not tested much as JennyLeeP is the one that started using the mod the most. I'll have to ask her if things seem better at her base:
(I have a very vague idea of what this all is but she likes to hide wires so I'm not going to touch this :P ).
We'll be testing the new version and I'll probably report back here.
Thanks a bunch!