1.10.2 Crash: Watching Server [Conduit Network and/or Ticking Issue?]
Opened this issue ยท 24 comments
Issue Description:
Crash description: Watching Server
What happens:
It's hard for me to discern what exactly happens leading up to the crash, because it happened just now with zero EnderIO machinery/piping in the loaded chunk vicinity to my knowledge. 2 players present in creative mode. One placing doors and the other placing banners. We were both physically in the same room and were super confused why we got the kick screen.
There was no use of conduits, neither RF nor liquid types. The closest building utilizing conduits is more than 16 chunks away, without a chunk loader.
What you expected to happen:
For the game to keep chugging along without incident
Steps to reproduce:
- It seems to be intermittent, since neither of us were using nor placing Ender IO items/blocks. I really wish I had more information.
2.
3.
...
Affected Versions (Do not use "latest"):
- EnderIO: EnderIO-1.10.2-3.0.1.120_beta.jar
- EnderCore: EnderCore-1.10.2-0.4.1.56-beta.jar
- Minecraft: 1.10.2
- Forge: 2093
Your most recent log file where the issue was present:
Watching server is a vanilla minecraft addition it'll crash/restart the server if it hangs up too long so don't read too much into that aspect of it. I've had a couple random ones caused by different mods so far (None by EnderIO though)
Yeah, that watchdog is the opposite of helpful.
In these crashes, it kills the server because the tick has taken too long. However, those Ender IO conduit handlers are run at the end of the tick---so we have no idea what happened during the tick and actually took that long to finish.
The interesting thing is, I tried something drastic and created a brand new map. My players weren't happy (I did reimport their properties at least) but it looks like whatever the hell was causing this is gone (for now). Players had to do a little cleaning up due to item and block ID reshuffling, but I think map stability is well worth the price.
Hopefully some of this data is useful to the devs/support guys, but please feel free to close the ticket if you feel its usefulness is gone, Thanks for all the comments.
New map would probably help as its a clean slate, some of mine have been just world gen or a mob glitching out somewhere so nothing world destroying but minecrafts thing shuts it down, You can disable the server watchdog afaik in server.properties if its being a pain with trivial things (especially world gen)
Got the same crash i believe http://pastebin.com/VcjqXU5G
EnderIO: EnderIO-1.10.2-3.0.1.120_beta
EnderCore: EnderCore-1.10.2-0.4.1.56-beta
Minecraft: 1.10.2
Forge: 2089
Did not get this crash with EnderIO-1.10.2-3.0.1.116_beta
I can't give you much info either, as i was not present when the crash happened.
So i just got this error and the crash report is listed here. https://gist.github.com/necrogami/1e70da88b103b525badd94ada9e96222
I just got the same crash as necrogami:
https://gist.github.com/rcooknet/b3955e680a53b145ca613a31df4cafa4
WyldLife 1.2.4 on Curse
EnderIO: EnderIO-1.10.2-3.0.1.138_beta.jar
EnderCore: EnderCore-1.10.2-0.4.1.60-beta.jar
Minecraft: 1.10.2
Forge: 2166
I think commit 5c9e3f4 is going to help a lot here. Just installed EnderIO - 1.10.2-3.1.157 logged in and got this
[11:10:20] [Server thread/INFO]: IcoSauro joined the game
[11:10:20] [Server thread/INFO] [journeymap]: IcoSauro joining dimension 0
[11:10:21] [Server thread/INFO] [EnderCore]: Sending server configs to client for com.enderio.core.common.config.ConfigHandler
[11:10:21] [Server thread/INFO] [Waila]: Player EntityPlayerMP['IcoSauro'/563, l='ModSaurUrno', x=-167.19, y=92.00, z=422.03] connected. Sending ping
[11:10:21] [Server thread/INFO] [journeymap]: Sending log in packet.
[11:10:22] [Server thread/WARN] [EnderIO]: Tried to add invalid conduit to network: AbstractConduit [getClass()=class crazypants.enderio.conduit.power.PowerConduit, getConduitConnections()=[north, east], getExternalConnections()=[], getNetwork()=AbstractConduitNetwork@3ed9899f [conduits=X: -178 Y: 92 Z: 443, X: -178 Y: 92 Z: 442, X: -178 Y: 92 Z: 441, X: -178 Y: 92 Z: 440, X: -178 Y: 92 Z: 444, ]]
[11:10:22] [Server thread/WARN] [EnderIO]: Tried to add invalid conduit to network: AbstractConduit [getClass()=class crazypants.enderio.conduit.power.PowerConduit, getConduitConnections()=[north, south], getExternalConnections()=[east], getNetwork()=AbstractConduitNetwork@3ed9899f [conduits=X: -178 Y: 92 Z: 443, ]]
[11:10:22] [Server thread/WARN] [EnderIO]: Tried to add invalid conduit to network: AbstractConduit [getClass()=class crazypants.enderio.conduit.power.PowerConduit, getConduitConnections()=[north, south], getExternalConnections()=[east], getNetwork()=AbstractConduitNetwork@3ed9899f [conduits=]]
[11:10:22] [Server thread/WARN] [EnderIO]: Tried to add invalid conduit to network: AbstractConduit [getClass()=class crazypants.enderio.conduit.power.PowerConduit, getConduitConnections()=[south], getExternalConnections()=[east], getNetwork()=AbstractConduitNetwork@3ed9899f [conduits=X: -178 Y: 92 Z: 443, X: -178 Y: 92 Z: 442, X: -178 Y: 92 Z: 441, ]]
[11:10:22] [Server thread/WARN] [EnderIO]: Tried to add invalid conduit to network: AbstractConduit [getClass()=class crazypants.enderio.conduit.power.PowerConduit, getConduitConnections()=[north, south], getExternalConnections()=[east], getNetwork()=AbstractConduitNetwork@3ed9899f [conduits=X: -178 Y: 92 Z: 443, X: -178 Y: 92 Z: 442, ]]
[11:10:22] [Server thread/WARN] [EnderIO]: Tried to add invalid conduit to network: AbstractConduit [getClass()=class crazypants.enderio.conduit.power.PowerConduit, getConduitConnections()=[west, east], getExternalConnections()=[], getNetwork()=AbstractConduitNetwork@3ed9899f [conduits=X: -178 Y: 92 Z: 443, X: -178 Y: 92 Z: 442, X: -178 Y: 92 Z: 441, X: -178 Y: 92 Z: 440, X: -178 Y: 92 Z: 444, X: -178 Y: 92 Z: 445, ]]
[11:10:22] [Server thread/WARN] [EnderIO]: Tried to add invalid conduit to network: AbstractConduit [getClass()=class crazypants.enderio.conduit.power.PowerConduit, getConduitConnections()=[north, south], getExternalConnections()=[], getNetwork()=AbstractConduitNetwork@3ed9899f [conduits=X: -178 Y: 92 Z: 443, X: -178 Y: 92 Z: 442, X: -178 Y: 92 Z: 441, X: -178 Y: 92 Z: 440, ]]
[11:10:22] [Server thread/WARN] [EnderIO]: Tried to add invalid conduit to network: AbstractConduit [getClass()=class crazypants.enderio.conduit.power.PowerConduit, getConduitConnections()=[north, east], getExternalConnections()=[], getNetwork()=AbstractConduitNetwork@3ed9899f [conduits=X: -178 Y: 92 Z: 443, X: -178 Y: 92 Z: 442, X: -178 Y: 92 Z: 441, X: -178 Y: 92 Z: 440, X: -178 Y: 92 Z: 444, ]]
[11:10:22] [Server thread/WARN] [EnderIO]: Tried to add invalid conduit to network: AbstractConduit [getClass()=class crazypants.enderio.conduit.power.PowerConduit, getConduitConnections()=[north, south], getExternalConnections()=[east], getNetwork()=AbstractConduitNetwork@3ed9899f [conduits=X: -178 Y: 92 Z: 443, ]]
[11:10:22] [Server thread/WARN] [EnderIO]: Tried to add invalid conduit to network: AbstractConduit [getClass()=class crazypants.enderio.conduit.power.PowerConduit, getConduitConnections()=[north, south], getExternalConnections()=[east], getNetwork()=AbstractConduitNetwork@3ed9899f [conduits=]]
[11:10:22] [Server thread/WARN] [EnderIO]: Tried to add invalid conduit to network: AbstractConduit [getClass()=class crazypants.enderio.conduit.power.PowerConduit, getConduitConnections()=[south], getExternalConnections()=[east], getNetwork()=AbstractConduitNetwork@3ed9899f [conduits=X: -178 Y: 92 Z: 443, X: -178 Y: 92 Z: 442, X: -178 Y: 92 Z: 441, ]]
[11:10:22] [Server thread/WARN] [EnderIO]: Tried to add invalid conduit to network: AbstractConduit [getClass()=class crazypants.enderio.conduit.power.PowerConduit, getConduitConnections()=[north, south], getExternalConnections()=[east], getNetwork()=AbstractConduitNetwork@3ed9899f [conduits=X: -178 Y: 92 Z: 443, X: -178 Y: 92 Z: 442, ]]
[11:10:22] [Server thread/WARN] [EnderIO]: Tried to add invalid conduit to network: AbstractConduit [getClass()=class crazypants.enderio.conduit.power.PowerConduit, getConduitConnections()=[west, east], getExternalConnections()=[], getNetwork()=AbstractConduitNetwork@3ed9899f [conduits=X: -178 Y: 92 Z: 443, X: -178 Y: 92 Z: 442, X: -178 Y: 92 Z: 441, X: -178 Y: 92 Z: 440, X: -178 Y: 92 Z: 444, X: -178 Y: 92 Z: 445, ]]
[11:10:22] [Server thread/WARN] [EnderIO]: Tried to add invalid conduit to network: AbstractConduit [getClass()=class crazypants.enderio.conduit.power.PowerConduit, getConduitConnections()=[up, west], getExternalConnections()=[north], getNetwork()=AbstractConduitNetwork@3ed9899f [conduits=X: -178 Y: 92 Z: 443, X: -178 Y: 92 Z: 442, X: -178 Y: 92 Z: 441, X: -178 Y: 92 Z: 440, X: -178 Y: 92 Z: 444, X: -178 Y: 92 Z: 445, X: -177 Y: 92 Z: 445, X: -176 Y: 92 Z: 445, ]]
[11:10:22] [Server thread/WARN] [EnderIO]: Tried to add invalid conduit to network: RedstoneConduit [network=RedstoneConduitNetwork [signals=, conduits=<-175,93,445><-175,92,445>] connections=[west] active=false]
[11:10:22] [Server thread/WARN] [EnderIO]: Tried to add invalid conduit to network: AbstractConduit [getClass()=class crazypants.enderio.conduit.power.PowerConduit, getConduitConnections()=[west, east], getExternalConnections()=[], getNetwork()=AbstractConduitNetwork@3ed9899f [conduits=X: -178 Y: 92 Z: 443, X: -178 Y: 92 Z: 442, X: -178 Y: 92 Z: 441, X: -178 Y: 92 Z: 440, X: -178 Y: 92 Z: 444, X: -178 Y: 92 Z: 445, X: -177 Y: 92 Z: 445, ]]
[11:10:22] [Server thread/WARN] [EnderIO]: Tried to add invalid conduit to network: AbstractConduit [getClass()=class crazypants.enderio.conduit.power.PowerConduit, getConduitConnections()=[down], getExternalConnections()=[north], getNetwork()=AbstractConduitNetwork@3ed9899f [conduits=X: -178 Y: 92 Z: 443, X: -178 Y: 92 Z: 442, X: -178 Y: 92 Z: 441, X: -178 Y: 92 Z: 440, X: -178 Y: 92 Z: 444, X: -178 Y: 92 Z: 445, X: -177 Y: 92 Z: 445, X: -176 Y: 92 Z: 445, X: -175 Y: 92 Z: 445, ]]
[11:10:22] [Server thread/WARN] [EnderIO]: Tried to add invalid conduit to network: RedstoneConduit [network=RedstoneConduitNetwork [signals=, conduits=] connections=[down] active=false]
[11:10:23] [Server thread/INFO] [minecolonies]: Starting AI job com.minecolonies.coremod.job.Farmer
[11:10:24] [Server thread/WARN]: Can't keep up! Did the system time change, or is the server overloaded? Running 2850ms behind, skipping 57 tick(s)
I'll report back if I get any crash in the next days. Hopefully the new checks will avoid the problem.
Thank you for working on this issue :)
Now that one is unexpected. I need to add the reason why it is invalid to that message...
Thx for the log!
So after a day of uptime I get way more warnings, roughly a few thousands. It took 50 seconds and then the server got unstuck, so the watchdog didn't killed it, however it is a close call.
I'll install the new release of EnderIO with the additional logging information as soon as it's released (feel free to ping me if you like). I'll collect the full log and post it
Oh, it seems this wasn't that unexpected. I forgot the change the text of the log message when I copied it to the other block. So it seems to be what I expected, a stale conduit in the network.
Nevertheless, now that I know it actually happens, I can add code that may help me to find out how it happens. I'll ping you here once I have a build.
Here, @enricotagliavini, use this build: http://ci.tterrag.com/job/EnderIO-1.10/158/ (once it's done). I won't push this to curse.
Installed and started. After about half an hour idling (with no login at all) the first login showed this. Now that there is some output it looks like these isseues are accumulating over time if there is nobody logged in or nobody in that area. This would explain why the first login works (it usually happens right after I restart the server).
Here is the full server log:
Thx. Try with this: http://ci.tterrag.com/job/EnderCore-1.10/63/ Do the log messages go away? Do your problems go away?
That was very quick! I started the server with the new EnderCore and left it there for about 8 hours. Upon fist login no warnings, that's a good sign. Let's see if it holds up with the next logins.
Thank you very much!
And with today it's almost 3 days without the problem appearing again. No warnings at all from the new code. It still takes something like 20 to 30 seconds to be able to interact with the world / fully load the world, but I have no idea if that's still Ender IO or another mod. I could set the watchdog to 20 seconds so I can get a stack trace. Log just says
[20:11:38] [Server thread/WARN]: Can't keep up! Did the system time change, or is the server overloaded? Running 26110ms behind, skipping 522 tick(s)
Nevertheless it's much better than before, it doesn't crash now.
Well turns out if I set max-tick-time to anything from 10 to 20 seconds forge will complain I'm using a negative value... obviously ;). This means to get the watchdog to kill the server again I might need weeks now (if it locks up at all with the fixes include). I cannot be 100% sure but I feel safe saying what Henry did is a lifesaver for who is experience the crash and it has my thumbs up for a release.
Thank you!
release with these changes is building now. It isn't fixing the real issue behind it, but it'll prevent Ender IO from being hit by it that hard.
max-tick-time is set in miliseconds, sure you used 20000 not 20?
reducing this option will cause an earlier forced shutdown, default is to wait 60000
also use some of the following jvm arguments to see if your garbage collector operation might be the culprit
-XX:+PrintHeapAtGC //prints your memory arrangement on every GC cycle (for deep debugging)
-XX:+PrintGC //prints some basic informations, can be used to make GCs vissible
-XX:+PrintGCDetails //prints some more details
-XX:+PrintGCApplicationStoppedTime //measures and shows the time that the GC blocked the application (only visible on full stop GC)
-XX:+PrintGCApplicationConcurrentTime //measures and shows the time the GC took parallel to the application
-XX:+PrintTenuringDistribution //shows a distribution of how your data is used (younger generations means volatile data that are thrown away ... inidcates a mod wasting objects , older generations are something like used world data)
Yeah I figured there was more to fix. But until we discover what it is this will be a decent Panacea at least. I'll keep an eye on it and see if I can find a way to discover more information.
Yes I'm sure I tried 20000 and not just 20, don't worry :). I also tried few other values but didn't found anything low enough working. The default 60000 works and also 120000 works.
I'll have a look at the GC, however it feels pretty tame. Doesn't look like there is excessive garbage collection happening and the server is not under memory pressure to free the memory. It's also a bit strange it happens only at login and them works as expected during normal gameplay.
I had two more crashes since last update. I updated just a couple of mods other than Ender IO since then. The symptoms are all the same, user logs in on a long running server, server gets stuck, watchdog kills it. However this time there is no Ender IO reference in the crash log. There is no mod reference at all to my best understanding. So it could be completely unrelated, but I mention it since the similarity is suspect.
When your server is killed, it is removing TileEntities of unloaded chunks from memory.
This is a bit of guesswork: I think what happens here is that while no player is online the game gets lazy and doesn't remove unloaded TileEntities. But even in this state, chunks get loaded and unloaded, so after a while, the list of TileEntities to remove gets so big that it takes too much time to clean it when a player logs in again.
This would also explain the following lines in the log (since the last logout to the next login)
[00:37:04] [Server thread/INFO]: IcoSauro lost connection: TranslatableComponent{key='disconnect.genericReason', args=[Internal Exception: java.io.IOException: Error while read(...): Connection reset by peer], siblings=[], style=Style{hasParent=false, color=null, bold=null, italic=null, underlined=null, obfuscated=null, clickEvent=null, hoverEvent=null, insertion=null}}
[00:37:04] [Server thread/INFO]: IcoSauro left the game
[02:30:36] [Server thread/WARN]: Can't keep up! Did the system time change, or is the server overloaded? Running 2718ms behind, skipping 54 tick(s)
[07:00:36] [Server thread/WARN]: Can't keep up! Did the system time change, or is the server overloaded? Running 2229ms behind, skipping 44 tick(s)
[07:30:36] [Server thread/WARN]: Can't keep up! Did the system time change, or is the server overloaded? Running 2001ms behind, skipping 40 tick(s) [08:45:36] [Server thread/WARN]: Can't keep up! Did the system time change, or is the server overloaded? Running 2207ms behind, skipping 44 tick(s)
[09:30:36] [Server thread/WARN]: Can't keep up! Did the system time change, or is the server overloaded? Running 2434ms behind, skipping 48 tick(s)
[19:00:37] [Server thread/WARN]: Can't keep up! Did the system time change, or is the server overloaded? Running 2443ms behind, skipping 48 tick(s) [20:00:38] [Server thread/WARN]: Can't keep up! Did the system time change, or is the server overloaded? Running 2907ms behind, skipping 58 tick(s)
[21:00:38] [Server thread/WARN]: Can't keep up! Did the system time change, or is the server overloaded? Running 2268ms behind, skipping 45 tick(s) [22:00:38] [Server thread/WARN]: Can't keep up! Did the system time change, or is the server overloaded? Running 2092ms behind, skipping 41 tick(s)
[22:23:24] [User Authenticator #11/INFO]: UUID of player RoSauroSa is 0e4cb237-31c7-4085-826e-fc85bab92bf5
[22:23:24] [Netty Epoll Server IO #1/INFO] [FML]: Client protocol version 2
[22:23:24] [Netty Epoll Server IO #1/INFO] [FML]: Client attempting to join with 36 mods : [email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected] [22:23:24] [Netty Epoll Server IO #1/INFO] [journeymap]: CLIENT [22:23:24] [Netty Epoll Server IO #1/INFO] [FML]: Attempting connection with missing mods [mercurius_updater] at CLIENT
[22:23:25] [Server thread/INFO] [FML]: [Server thread] Server side modded connection established
[22:23:25] [Server thread/INFO]: RoSauroSa[/78.43.43.79:56973] logged in with entity id 651382 at (-172.0, 92.0, 424.0)
[22:23:25] [Server thread/INFO]: RoSauroSa joined the game
[22:23:25] [Server thread/INFO] [journeymap]: RoSauroSa joining dimension 0
[22:23:25] [Server thread/INFO] [EnderCore]: Sending server configs to client for com.enderio.core.common.config.ConfigHandler
[22:23:25] [Server thread/INFO] [Waila]: Player EntityPlayerMP['RoSauroSa'/651382, l='ModSaurUrno', x=-172.00, y=92.00, z=424.00] connected. Sending ping
[22:23:25] [Server thread/INFO] [journeymap]: Sending log in packet.
[22:24:13] [User Authenticator #12/INFO]: UUID of player RoSauroSa is 0e4cb237-31c7-4085-826e-fc85bab92bf5
[22:24:25] [Server Watchdog/FATAL]: A single server tick took 60.00 seconds (should be max 0.05)
[22:24:25] [Server Watchdog/FATAL]: Considering it to be crashed, server will forcibly shutdown.
See all those "Can't keep up!"? Nobody is on the server and the machine itself is quite idle. Surely I have a backup run, but that happens only once and not at the named times.