mojira.dev
MC-72806

When using /stop server executes the shutdown sequence twice (and hangs if players are online)

This issue relates to (duplicates/adds to?): MC-63802

When using /stop server executes the shutdown sequence twice (and hangs if players are online).

There is actually two (closely connected) issues here:
1. The shutdown sequence shouldn't be processed twice when the server got shut down with /stop
2. The second shutdown sequence hangs when closing the open connections

When stopping a server with at least one player online the console output will look like this:

Console Output

[23:10:19] [Server thread/INFO]: Panda4994 joined the game
[23:10:22] [Server thread/INFO]: [Panda4994: Stopping the server]
[23:10:22] [Server thread/INFO]: Stopping server
[23:10:22] [Server thread/INFO]: Saving players
[23:10:22] [Server thread/INFO]: Saving worlds
[23:10:22] [Server thread/INFO]: Saving chunks for level 'mcpworld'/Overworld
[23:10:22] [Server thread/INFO]: Saving chunks for level 'mcpworld'/Nether
[23:10:22] [Server thread/INFO]: Saving chunks for level 'mcpworld'/The End
[23:10:22] [Server Shutdown Thread/INFO]: Stopping server
[23:10:22] [Server Shutdown Thread/INFO]: Saving players

The process doesn't stop after that (This might be dependent on the enviroment).

As you can see "Stopping server" appears twice.
Once executed by the "Server thread" and once by the "Server Shutdown Thread" while the second one hangs after saving the players.

The first time it runs it's the normal shutdown from when the server gets stopped normally (It's MCP-Names but should be understandable what's meant).

MinecraftServer.java

public void run() {
	try {
		...
		while (this.serverRunning) {	// Main loop
			...
		}
		...
	}
	catch (...) {...}
	finally {
		...
		this.stopServer();	// What I call shutdown sequence. Doing these things: "Stopping server", "Saving players", "Saving worlds"
		this.serverStopped = true;
		...
		this.systemExitNow();	// Just calls System.exit(0);
	}
}

The second one is a shutdown hook which gets initialized at (pretty much) the end of the main method.

MinecraftServer.java

public static void main(String[] args) {
	...
	Runtime.getRuntime().addShutdownHook(new Thread("Server Shutdown Thread") {
		public void run() {
			dedicatedServerInstance.stopServer();	// What I call shutdown sequence. Doing these things: "Stopping server", "Saving players", "Saving worlds"
		}
	});
	...
}

Fix for issue 1.
A fix for the issue that the shutdown sequence is run twice is rather simple.

Just add a check to the shutdown hook that it only runs if the shutdown sequence didn't run before.
Like this:

MinecraftServer.java (changed)

public static void main(String[] args) {
	...
	Runtime.getRuntime().addShutdownHook(new Thread("Server Shutdown Thread") {
		public void run() {
			if (!dedicatedServerInstance.isServerStopped()) {
				dedicatedServerInstance.stopServer();
			}
		}
	});
	...
}

This also fixes the server hanging when using /stop as the shutdown hook only runs if the first shutdown failed.
The second shutdown sequence is still broken though.

Fix for issue 2.
For the problem that the shutdown hook hangs I don't have a fix yet.
But I tracked down the issue a bit.
It hangs after closing the connections to the players while creating a thread.

NetHandlerPlayServer.java

public void kickPlayerFromServer(String reason) {
	...
	// Futures.getUnchecked(...) never returns when called by the shutdown hook
	Futures.getUnchecked(this.serverController.addScheduledTask(new Runnable() {
		public void run() {
			NetHandlerPlayServer.this.netManager.checkDisconnected();
		}
	}));
}

I assume that it hangs in a deadlock or something like that since the documentation of addShutdownHook() warns about it (http://docs.oracle.com/javase/7/docs/api/java/lang/Runtime.html#addShutdownHook%28java.lang.Thread%29).
I didn't look into Futures too much so I'm not sure where exactly it's coming from.

The closest to a fix I got for that would be to remove the kicking of player in the shutdown hook as it doesn't work at the moment anyways.

But as long as /stop works fine again and doesn't mess up our scripts to start and stop server I'm fine with it 🙂

Linked issues

Comments

migrated

I experience the same issues (annoyances) with Panda

I can stop the server with people/clients joined (no hangs), but I can only stop the server with /stop at the server console (regardless whether clients are connected or not).
The /stop command does get executed twice, once server thread and server shutdown thread
Running /stop from a connected client makes the server hang shutting down (as Panda said)

I use Ubuntu 14.04.1 with OpenJDK 7

migrated

I am not a pro at java but to me it looks like the last piece of code is just missing 2 )'s at the end.

From this: Futures.getUnchecked(this.serverController.addScheduledTask(new Runnable() {
to this: Futures.getUnchecked(this.serverController.addScheduledTask(new Runnable())) {

EDIT: Actually never mind. They are at the end ._.

Panda4994

Still happens in 1.8.1 pre 1 and pre 2

Panda4994

The executing twice still happens in 1.8.1-pre3. Sometimes causing an exception (see below).
But the main issue of hanging seems to be gone. Thank you 🙂

Console Output

$ java -jar minecraft_server.1.8.1-pre3.jar
[21:22:36] [Server thread/INFO]: Starting minecraft server version 1.8.1-pre3
[21:22:36] [Server thread/INFO]: Loading properties
[21:22:36] [Server thread/INFO]: Default game type: SURVIVAL
[21:22:36] [Server thread/INFO]: Generating keypair
[21:22:36] [Server thread/INFO]: Starting Minecraft server on *:25565
[21:22:36] [Server thread/INFO]: Using epoll channel type
[21:22:36] [Server thread/INFO]: Preparing level "world"
[21:22:36] [Server thread/INFO]: Preparing start region for level 0
[21:22:37] [Server thread/INFO]: Done (0,954s)! For help, type "help" or "?"
[21:22:38] [User Authenticator #1/INFO]: UUID of player Panda4994 is 225a47c7-b792-4233-8d6d-d51e102b08f8
[21:22:38] [Server thread/INFO]: Panda4994/127.0.0.1:44929 logged in with entity id 261 at (-44.940450747439314, 73.0, 27.867319105772793)
[21:22:38] [Server thread/INFO]: Panda4994 joined the game
[21:22:51] [Server thread/INFO]: [Panda4994: Stopping the server]
[21:22:51] [Server thread/INFO]: Stopping server
[21:22:51] [Server thread/INFO]: Saving players
[21:22:51] [Server thread/INFO]: Saving worlds
[21:22:51] [Server thread/INFO]: Saving chunks for level 'world'/Overworld
[21:22:51] [Server thread/INFO]: Saving chunks for level 'world'/Nether
[21:22:51] [Server thread/INFO]: Saving chunks for level 'world'/The End
2014-10-28 21:22:52,167 ERROR Attempted to append to non-started appender SysOut
[21:22:52] [Server Shutdown Thread/INFO]: Stopping server
2014-10-28 21:22:52,168 ERROR Attempted to append to non-started appender ServerGuiConsole
Exception in thread "Server Shutdown Thread" org.apache.logging.log4j.core.appender.AppenderLoggingException: Attempted to append to non-started appender ServerGuiConsole
at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:89)
at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:425)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:406)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:367)
at org.apache.logging.log4j.core.Logger.log(Logger.java:110)
at org.apache.logging.log4j.spi.AbstractLogger.info(AbstractLogger.java:1011)
at net.minecraft.server.MinecraftServer.s(SourceFile:373)
at pf.run(SourceFile:716)

migrated

This issue is still occuring in 1.8.1-pre3

Panda4994

Nathan Adams

Community Consensus

Minecraft 1.8, Minecraft 1.8.1-pre2

Minecraft 1.8.1-pre3

Retrieved