• Minecraft daily restart often failing since upgrading from McMyAdmin

Minecraft daily restart often failing since upgrading from McMyAdmin

  • 248 Views
  • Last Post 10 June 2020
  • Topic Is Solved
JonathanL posted this 06 May 2020

I have scheduled a daily task to restart our Minecraft server, it seems that some mornings it fails to restart saying it gave up after 5 tries, but looking in the logs I don't see any record of it trying even once.

There is an exception thrown by one of the Minecraft mods in the logs as the server is shutting down, but I would not expect that to prevent it trying to restart after.

I only upgraded from McMyAdmin personal edition a few days ago and that never failed to restart the server.

Diagnostics Data

OS: Windows
Platform: Microsoft Windows Server 2012 R2 Standard
System Type: x86_64
Virtualization: None
Module: ADSModule
Loaded Plugins: FileManagerPlugin, EmailSenderPlugin, WebRequestPlugin, LocalFileBackupPlugin
Application Name: AMPService
Application Version: 1.9.9.0
Release Stream: Release
Build Date: 28/04/2020 20:41
InstanceID: d25e424b-ea30-4d9f-9dea-4ff70b1dfcbe
Last Executable: C:\AMPDatastore\Instances\Minecraft01\AMP.exe
Last Arguments: +Core.Webserver.Port "8091" +Core.Webserver.IPBinding "0.0.0.0" +MinecraftModule.Minecraft.PortNumber "25565"

And below are some snippets from the logs around the time of the restart.

From <instance_folder>/Minecraft/Logs/fml-server-latest.log:

[04:00:08] [Server thread/ERROR] [FML/]: Exception caught during firing event net.minecraftforge.event.world.WorldEvent$Unload@2696c469:
net.minecraft.util.ReportedException: Exception while updating neighbours
    at net.minecraft.world.World.func_147460_e(World.java:730) ~[ahb.class:?]
    at net.minecraft.world.World.func_147459_d(World.java:653) ~[ahb.class:?]
    at extracells.part.PartFluidLevelEmitter.notifyTargetBlock(PartFluidLevelEmitter.java:105) ~[PartFluidLevelEmitter.class:?]
    at extracells.part.PartFluidLevelEmitter.onStackChange(PartFluidLevelEmitter.java:133) ~[PartFluidLevelEmitter.class:?]
    ...

From <instance_folder>/Minecraft/Logs/latest.log:

[04:00:01] [Server thread/INFO]: Stopping the server
[04:00:08] [Server thread/ERROR] [FML/]: Exception caught during firing event net.minecraftforge.event.world.WorldEvent$Unload@2696c469:
net.minecraft.util.ReportedException: Exception while updating neighbours
    at net.minecraft.world.World.func_147460_e(World.java:730) ~[ahb.class:?]
    at net.minecraft.world.World.func_147459_d(World.java:653) ~[ahb.class:?]
    at extracells.part.PartFluidLevelEmitter.notifyTargetBlock(PartFluidLevelEmitter.java:105) ~[PartFluidLevelEmitter.class:?]
    at extracells.part.PartFluidLevelEmitter.onStackChange(PartFluidLevelEmitter.java:133) ~[PartFluidLevelEmitter.class:?]
    ...

From <instance_folder>/AMP_Logs/AMPLOG_<date>.log:

[04:00:01] [Server thread/INFO]: Stopping the server
[04:00:08] [Server thread/ERROR]: Exception stopping the server
net.minecraft.util.ReportedException: Exception while updating neighbours
    at net.minecraft.world.World.func_147460_e(World.java:730) ~[ahb.class:?]
    at net.minecraft.world.World.func_147459_d(World.java:653) ~[ahb.class:?]
    at extracells.part.PartFluidLevelEmitter.notifyTargetBlock(PartFluidLevelEmitter.java:105) ~[PartFluidLevelEmitter.class:?]
    at extracells.part.PartFluidLevelEmitter.onStackChange(PartFluidLevelEmitter.java:133) ~[PartFluidLevelEmitter.class:?]
    ...
[04:00:09] [System:admin Warning] : Server failed to start 5 times, not restarting.
[05:00:02] [System Activity]      : Creating Backup: Scheduled Backup</date></instance_folder></instance_folder></instance_folder>

amp minecraft
Order By: Standard | Newest | Votes
Mike posted this 06 May 2020

It's most likely a permissions issue but it's hard to tell because you appear to have trimmed the logs. Is ADS running as a service?

JonathanL posted this 06 May 2020

I tried pasting more logs initially, but there is a 6000 character limit.

I've put the untrimmed logs on PasteBin (you're going to need to change .net links to .com as your server was blocking this post):
latest.log
fml-latest.log
amplog

It started up fine yesterday morning, but the morning before it failed, so a permission problem seems unlikely. Also, just saying start server from the AMP ui is enough to start it.

EDIT: To answer your question, yes, it's running as a service which was set up by the installer, which I didn't change at all. When setting it up, I actually had to change permission of the folders to Everyone in Windows for it to be able to start the Minecraft server.

This is just a personal server I run and manage from home for myself and a few other people play on.

JonathanL posted this 07 May 2020

What's the next step here to try get to the bottom of this?

Mike posted this 07 May 2020

No idea to be honest. Anything that happens once the Minecraft process is started is out of AMPs control. The logs show this exception:

[04:00:08] [Server thread/ERROR]: Exception caught during firing event net.minecraftforge.event.world.WorldEvent$Unload@2696c469:
net.minecraft.util.ReportedException: Exception while updating neighbours

Which would possibly suggest corrupted world data, but you'd have to forward that error to the forge/modpack developers. This isn't an AMP issue.

JonathanL posted this 10 May 2020

While it is true that a mod is not shutting down gracefully, I consider it a bug in AMP that it is not at least trying to start the server after.

If you look in the logs after that, there is nothing indicating that AMP tried restarting the server even once, only an entry saying it's giving up because it tried 5 times, which is lie from what the logs are showing.

I am a highly experienced C# developer, so feel free to ask technical questions of me.

Mike posted this 10 May 2020

Have you got debug logging turned on so you can see when AMP is starting the process?

JonathanL posted this 13 May 2020

Happened again this morning after I managed to enable debug logging the other day.

Logs of the Minecraft01 AMP instance (nothing omitted between first and last entry):

[04:00:12] [Minecraft Debug]      : Application state changed from Restarting to Stopped
[04:00:12] [System Warning]       : Server failed to start 5 times, not restarting.
[04:00:12] [Minecraft Debug]      : Application state changed from Stopped to Failed
[04:00:12] [Core Debug]           : Task Restarting Server... () ended: Finished

Full log for the day: https://hastebin.com/axapuhufol.rb

The stuff at 8:30 was me manually starting the server from the AMP control panel, but then changing my mind and aborting as I decided to do Windows Updates first.

Mike posted this 13 May 2020

Definitely a forge issue, you should give that error log to the developer of the modpack you're running.

JonathanL posted this 14 May 2020

AMP itself logs this (NOT Minecraft or Forge):
[04:00:12] [Minecraft Debug] : Application state changed from Restarting to Stopped

And the next thing it logs instantly after is (again, NOT Minecraft or Forge) this:
[04:00:12] [System Warning] : Server failed to start 5 times, not restarting.

How could that be a fault in any place besides in AMP?

What is happening between those two entries that it thinks it tried starting 5 times?

Mike posted this 14 May 2020

"Application state changed" does not necessarily mean "AMP changed the state" it is reporting a change of state that has occurred for any reason.

In this case, it means that AMP was trying to restart the application, and then the process stopped of its own accord when AMP wasn't expecting (it's expecting it to transition to the Running state, which is triggered by the 'Done' message)

If AMP tries to start the application and it doesn't reach the "Started" state 5 consecutive times, then it won't try again because the application isn't working.

When AMP stops the server (either because of a scheduled task, or the user requested it) then you get the following:

[04:00:00] [System Info] : Application stop requested

Which in your case is preceded by scheduler logs saying that's what it's doing.

This is nothing to do with AMP, any situation where you're getting errors/exceptions from the Minecraft server itself is exclusively down to the Minecraft server and not AMP.

Your Minecraft server is not functioning correctly, Forge is throwing errors and exceptions all over the place - and as such is failing to start. It may well be failing in such a way that it is able to start some times but not others. But as I have said, you need to give those stack traces to the forge/modpack developers to find out what's going on - or try taking a backup of your server and reset it, slowly re-introducing your data back until something breaks.

JonathanL posted this 14 May 2020

If AMP tries to start the application and it doesn't reach the "Started" state 5 consecutive times, then it won't try again because the application isn't working.

But the problem is that AMP isn't even trying to start the server once, never mind 5 times, there's nothing in the logs of it attempting to do so, it just instantly complains that it gave up after supposedly trying 5 times with no evidence of actually trying at all.

AMP shouldn't care about non-graceful shutdowns after it's expecting the server to stop, it's good for it to log a warning when encountered, but then otherwise it should just try start up the server again. If after trying to start up the 5 times, then it's fair for it to give up.

Here's my theory of what's going on and why this seems to be intermittent:

Day 1:
04:00 AMP initiates server shutdown.
04:10 AMP detects ungraceful shutdown,
04:10 AMP sets failed started count to 1 of 5.
04:10 AMP restarts the server.

Day 2:
04:00 AMP initiates server shutdown.
04:10 AMP detects ungraceful shutdown,
04:10 AMP sets failed started count to 2 of 5.
04:10 AMP restarts the server.

Day 3:
04:00 AMP initiates server shutdown.
04:10 AMP detects ungraceful shutdown,
04:10 AMP sets failed started count to 3 of 5.
04:10 AMP restarts the server.

Day 4:
04:00 AMP initiates server shutdown.
04:10 AMP detects ungraceful shutdown,
04:10 AMP sets failed started count to 4 of 5.
04:10 AMP restarts the server.

Day 5:
04:00 AMP initiates server shutdown requested.
04:10 AMP detects ungraceful shutdown,
04:10 AMP sets failed started count to 5 of 5.
04:10 AMP gives up.

It's poor behaviour of AMP if this is what's happening, once AMP initiates a shutdown then any problems detected between then and before it attemptes to spawn java.exe again should not be regarded as a startup error.

I've acknowledged the server mods have problems, but that's besides the point because AMP appears to have a robustness problem in this kind of a scenario.

Mike posted this 14 May 2020

Is the server transitioning to the "Running" state? This is identified by the available buttons switching to say Stop, Restart and Sleep. The 'Startup Failures' counter is reset when it hits the running state.

JonathanL posted this 14 May 2020

This morning it restarted fine, despite that commonly thrown exception on shutdown and the same for the 12th (the 13th was the last day a problem occurred).

Right now the instance status shows the Restart, Stop and Sleep buttons under the live updating metrics.

The log entries around the restart are:

[04:00:00] [Core Debug]           : Running scheduled task Event.MinecraftModule.SaveChanges for trigger Every 15 minutes
[04:00:00] [Core Debug]           : Running scheduled task Event.MinecraftModule.Restart for trigger At 04h00 daily
[04:00:00] [System Info]          : Application stop requested
[04:00:00] [Minecraft Debug]      : Application state changed from Ready to Restarting
<snip>
[04:00:10] [Minecraft Debug]      : Application state changed from Restarting to Stopped
[04:00:10] [Minecraft Debug]      : Application state changed from Stopped to PreStart
[04:00:10] [Minecraft Info]       : Java located at C:\Program Files (x86)\Common Files\Oracle\Java\javapath\java.exe
[04:00:10] [Minecraft Warning]    : Java installation may be 32-bit! This could prevent the Minecraft server from starting.
[04:00:10] [Minecraft Debug]      : Hash for ./Minecraft/ForgeMod.jar: a1fbd0adc4612a6596efb4264ec2d9ec
[04:00:10] [Minecraft Info]       : Using 'Forge' compatibility mode.
[04:00:10] [Minecraft Debug]      : Java located at: C:\Program Files (x86)\Common Files\Oracle\Java\javapath\java.exe
[04:00:10] [Minecraft Debug]      : Java start arguments: -Xmx8192M -XX:+UseConcMarkSweepGC -XX:+CMSIncrementalPacing -XX:ParallelGCThreads=8 -d64 -Dfml.queryResult=confirm -jar ForgeMod.jar nogui
[04:00:10] [Minecraft Debug]      : Starting process C:\Program Files (x86)\Common Files\Oracle\Java\javapath\java.exe
[04:00:10] [Minecraft Debug]      : Working Directory: ./Minecraft/
[04:00:10] [Minecraft Debug]      : Arguments: -Xmx8192M -XX:+UseConcMarkSweepGC -XX:+CMSIncrementalPacing -XX:ParallelGCThreads=8 -d64 -Dfml.queryResult=confirm -jar ForgeMod.jar nogui
[04:00:10] [Minecraft Debug]      : Started process with ID 5468
[04:00:10] [Minecraft Debug]      : Application state changed from PreStart to Starting
<snip>
[04:01:35] [Core Debug]           : Task Restarting Server... () ended: Finished
[04:01:35] [Minecraft Debug]      : Application state changed from Starting to Ready

I don't see any other Application state changed entries after that.

The 'Startup Failures' counter is reset when it hits the running state.

That shoots down my theory, but it puts my mind at rest in that regard.

Mike posted this 14 May 2020

The fact that you're using 32 bit Java probably isn't helping. You should uninstall any Java versions and just make sure Java 8 64 bit is installed.

JonathanL posted this 14 May 2020

It's the 64 bit installed:

[04:00:11] [main/INFO]: Loading tweak class name cpw.mods.fml.common.launcher.FMLServerTweaker
[04:00:11] [main/INFO]: Using primary tweak class name cpw.mods.fml.common.launcher.FMLServerTweaker
[04:00:11] [main/INFO]: Calling tweak class cpw.mods.fml.common.launcher.FMLServerTweaker
[04:00:11] [main/INFO]: Forge Mod Loader version 7.99.40.1614 for Minecraft 1.7.10 loading
[04:00:11] [main/INFO]: Java is Java HotSpot(TM) 64-Bit Server VM, version 1.8.0_251, running on Windows Server 2012 R2:amd64:6.3, installed at C:\Program Files\Java\jre1.8.0_251
[04:00:12] [main/INFO]: [AppEng]: Core Init

JonathanL posted this 14 May 2020

How do we dig further into the issue that it's not trying restart the server and it incorrectly thinking it failed 5 times?

JonathanL posted this 15 May 2020

This morning it happened and there wasn't even an exception this time on shutdown:

https://hastebin.com/owifemacoc.sql

JonathanL posted this 19 May 2020

@mike, this happened again this morning.

I am a software developer with close to two decades of professional experience, please give the professional courtesy of at least trying to work with me to get to the bottom of this. As an added benefit on your side, AMP will be better off for it afterwards.

There can be no doubt at this point that AMP is not as robust as it needs to be when trying to restart the server. At the very least more logging is needed as to what is going on. In particular, what is AMP actually doing between the following two log entries:
[04:00:12] [Minecraft Debug] : Application state changed from Restarting to Stopped
[04:00:12] [System Warning] : Server failed to start 5 times, not restarting.

Mike posted this 19 May 2020

The latest nightly build has an extra set of logs in it that show you when its incrementing the failure counter, or when it's resetting it back to 0. Although you really should be looking into what's causing the MC server to crash in the first place. Relying on AMP to restart an unreliable and crashing server is something of a hack.

JonathanL posted this 19 May 2020

Thanks, appreciate the response. I'll try get the nightly and let you know what happens.

Although you really should be looking into what's causing the MC server to crash in the first place.

Like I said for the previous time it failed to restart, there was no crash or exception in the logs, so I really don't think those exceptions have anything to do with this problem at all. When it does throw those exception it's some clean-up thing on shutdown which evidently doesn't corrupt anything, so while not ideal, in practice it's not a real problem.

That being said, I have looked at any exceptions in the logs and none of them appear to affect the stability of the server, it was running perfectly on McMyAdmin and this problem only started after moving to AMP. I wouldn't have posted here if I wasn't absolutely sure it wasn't related to the mods.

It's an old version of the game (1.7.10) and the mod community moved on from it a while back. We never had a need to try get help for mods in the past and given how old it is now we wouldn't even think of trying to get any kind of help with the mods now, we accept we're fully on our own.

JonathanL posted this 10 June 2020

@mike, updated the server a while back to 1.9.9.8 and haven't been watching too closely, but this morning we noticed it happened again.

Logs here: https://hastebin.com/omaxazahoq.sql

Mike posted this 10 June 2020

I've just taken another look at this, the logic that's triggering this is where AMP will not attempt a second restart if the first one failed within 5 seconds. This prevents AMP from cycling 5 times over in rapid succession if the server isn't going to start.

So your server is restarting as part of its schedule, it then fails to restart and takes less than 5 seconds to fail, AMP treats this as a "The server isn't in a state where it's able to start" situation and doesn't attempt to restart it.

Comes back to what I've been saying, you should fix what's causing the restart to fail instead.

If you're desperate not to do this, you can use the scheduler to try and start the server again a minute later.

It's showing the wrong log message for this situation (which I've now fixed) - but AMP is functioning as intended.

JonathanL posted this 10 June 2020

But as can be seen in the those latest logs, there is no restart failure of the server itself or any indication of what is failing.

JonathanL posted this 10 June 2020

As per these lines, there is no indication of anything failing:

[04:00:10] [Server thread/INFO]: RFTools: server is stopping. Shutting down gracefully
[04:00:11] [Minecraft Debug] : Application state changed from Restarting to Stopped
[04:00:11] [Minecraft Warning] : Server failed to start 5 times, not restarting.
[04:00:11] [Minecraft Debug] : Application state changed from Stopped to Failed
[04:00:11] [Core Debug] : Task Restarting Server... () ended: Finished

Live Chat Register to post
Categories
Search
Popular Tags
This Weeks High Earners
Hot Topics
Close