Occasionally, but not always, I get the following behaviour when shutting down the server
gsadmin:gsadmin@polaris:/storage/games/minecraft/17-test$ java -jar minecraft_server.1.7.2.jar --nogui
[11:25:00] [Server thread/INFO]: Starting minecraft server version 1.7.2
[11:25:00] [Server thread/INFO]: Loading properties
[11:25:00] [Server thread/INFO]: Default game type: SURVIVAL
[11:25:00] [Server thread/INFO]: Generating keypair
[11:25:00] [Server thread/INFO]: Starting Minecraft server on *:25567
[11:25:00] [Server thread/INFO]: Preparing level "world"
[11:25:00] [Server thread/INFO]: Preparing start region for level 0
[11:25:01] [Server thread/INFO]: Done (0.746s)! For help, type "help" or "?"
[11:25:10] [Server thread/INFO]: Unknown command. Try /help for a list of commands
[11:25:33] [Server thread/INFO]: Unknown command. Try /help for a list of commands
stop
[11:25:36] [Server thread/INFO]: Stopping the server
[11:25:36] [Server thread/INFO]: Stopping server
[11:25:36] [Server thread/INFO]: Saving players
[11:25:36] [Server thread/INFO]: Saving worlds
[11:25:36] [Server thread/INFO]: Saving chunks for level 'world'/Overworld
[11:25:36] [Server thread/INFO]: Saving chunks for level 'world'/Nether
[11:25:36] [Server thread/INFO]: Saving chunks for level 'world'/The End
[11:25:36] [Server Shutdown Thread/INFO]: Stopping server
2013-10-28 11:25:36,620 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.n(SourceFile:287)
at kx.run(SourceFile:605)Code analysis by @unknown in this comment.
Linked issues
is duplicated by 12
MC-45051
ERROR Attempted to append to non-started appender ServerGuiConsole
Resolved
MC-52794
Error on server close (1.7.7 & 1.7.8)
Resolved
MC-54408
Server throws exceptions after stopping
Resolved
MC-61477
Server crashes when stopped before EULA agreed to
Resolved
MC-73537
Error appears when executing /stop from server console command line
Resolved
Comments 27
I can confirm this behavior and i have found something interesting:
When i start the server typing the command directly at the server-console (like with the physical keyboard that is connected to the server-pc) i get the error as mentioned, but when i start the server remote from my windows-laptop with putty, i don't get the error...
Duplicated by MC-45051.
Please add 14w03b to Affected Versions.
I wrote this comment for MC-78120, the problem might be caused by LOG4J
This particular bug could maybe be fixed by using a newer version of log4j. The latest version is currently version 2.5, however Minecraft is using version 2.0-beta9 (Windows:
%appdata%\.minecraft\libraries\org\apache\logging\log4j\log4j-core). Additionally there is a similar looking bug that affects version 2.0-beta9 but is fixed in version 2.1: LOG4J2-392.
Please link to this comment in the description
The following is based on a decompiled version of Minecraft 1.10 using MCP 9.30.
I am not too familiar with how LOG4j exactly works or if a locked object can cause this problem, but maybe this is the case here.
The reason could be that a daemon thread is created to write the log in the server gui (net.minecraft.server.gui.MinecraftServerGui.getLogComponent().new Runnable() {...}.()). This thread calls the following method:
public static String getNextLogEvent(final String queueName) {
QueueLogAppender.QUEUE_LOCK.readLock().lock();
final BlockingQueue<String> queue = QueueLogAppender.QUEUES.get(queueName);
QueueLogAppender.QUEUE_LOCK.readLock().unlock();
if (queue != null) {
try {
return queue.take();
}
catch (InterruptedException ex) {}
}
return null;
}It looks like this bug happens always when the "Server Shutdown Thread" stops the server. Maybe the problem is that the logging thread was terminated while it locked the QUEUE_LOCK which prevented LOG4j from logging somehow.
Like I said I don't know if this can really cause this or if there might be a different reason.
Can someone please check, if this still applies to 1.15.2 or the latest 1.16 development snapshot (currently that is 20w07a)?
I think this was fixed in 18w47a. 18w46a and prior versions (e.g. 1.13.2) had this for the shutdown hook:
18w46a, MinecraftServer.main
dedicatedserver.startServerThread();
Thread thread = new Thread("Server Shutdown Thread") {
public void run() {
dedicatedserver.stopServer();
}
};
thread.setUncaughtExceptionHandler(new DefaultUncaughtExceptionHandler(LOGGER));
Runtime.getRuntime().addShutdownHook(thread);while 18w47a has this:
18w47a, MinecraftServer.main
dedicatedserver.startServerThread();
Thread thread = new Thread("Server Shutdown Thread") {
public void run() {
dedicatedserver.initiateShutdown(true);
}
};
thread.setUncaughtExceptionHandler(new DefaultUncaughtExceptionHandler(LOGGER));
Runtime.getRuntime().addShutdownHook(thread);18w47a, MinecraftServer.initiateShutdown
public void initiateShutdown(boolean waitForServer) {
this.serverRunning = false;
if (waitForServer) {
try {
this.serverThread.join();
} catch (InterruptedException interruptedexception) {
LOGGER.error("Error while shutting down", (Throwable)interruptedexception);
}
}
}The main thread checks serverRunning each tick and stops if it's false (this is also used by e.g. /stop). The gist of this is that the main thread will handle the logging, and I think that's better than doing the shutdown and logging in the shutdown hook (according to this SO post you aren't allowed to log in shutdown hooks as log4j does its own teardown at that point, unless you do some special configuration).
The difference can be seen by comparing the output for a 18w46a shutting down and an 18w47a server shutting down:
18w46a
[15:32:39] [Server thread/INFO]: Stopping the server
[15:32:39] [Server thread/INFO]: Stopping server
[15:32:39] [Server thread/INFO]: Saving players
[15:32:39] [Server thread/INFO]: Saving worlds
[15:32:39] [Server thread/INFO]: Saving chunks for level 'world'/minecraft:the_end
[15:32:39] [Server thread/INFO]: ThreadedAnvilChunkStorage (DIM1): All chunks are saved
[15:32:39] [Server thread/INFO]: Saving chunks for level 'world'/minecraft:the_nether
[15:32:39] [Server thread/INFO]: ThreadedAnvilChunkStorage (DIM-1): All chunks are saved
[15:32:39] [Server thread/INFO]: Saving chunks for level 'world'/minecraft:overworld
[15:32:44] [Server thread/INFO]: ThreadedAnvilChunkStorage (world): All chunks are saved
[15:32:48] [Server Shutdown Thread/INFO]: Stopping server
[15:32:48] [Server Shutdown Thread/INFO]: Saving playersThe "saving players" line does not always show up on the server thread; sometimes, it's present, and other times, it's not. Sometimes it also gets further e.g. to "Saving worlds".
18w47a
[15:20:10] [Server thread/INFO]: Stopping the server
[15:20:10] [Server thread/INFO]: Stopping server
[15:20:10] [Server thread/INFO]: Saving players
[15:20:10] [Server thread/INFO]: Saving worlds
[15:20:10] [Server thread/INFO]: Saving chunks for level 'world'/minecraft:overworld
[15:20:13] [Server thread/INFO]: ThreadedAnvilChunkStorage (world): All chunks are saved
[15:20:13] [Server thread/INFO]: Saving chunks for level 'world'/minecraft:the_nether
[15:20:13] [Server thread/INFO]: ThreadedAnvilChunkStorage (DIM-1): All chunks are saved
[15:20:13] [Server thread/INFO]: Saving chunks for level 'world'/minecraft:the_end
[15:20:13] [Server thread/INFO]: ThreadedAnvilChunkStorage (DIM1): All chunks are savedNote that nothing is printed by the shutdown thread. Therefore, it should be impossible for a message to be logged while log4j is shutting down.
Unfortunately, I haven't been able to reproduce in 18w46a, and I can't test 18w47a due to MC-139758 and similar issues. I was able to reproduce in 1.11.2, though.
(One other thing: the implementation of QueueLogAppender hasn't changed. However, I don't think it was responsible for the underlying issue, as ERROR Attempted to append to non-started appender File could also happen (e.g. MC-101810))
Resolving cannot reproduce. Further research indicates that log4j was updated from 2.0-beta9 to 2.8.1 in 17w15a, and I have been able to reproduce the "ERROR Attempted to append to non-started appender File" message in 17w14a but not 17w16a (17w15a is untestable thanks to MC-115797). LOG4J2-392 was fixed in 2.0-rc2, which seems similar to this issue. There may or may not have been a second bug with the async nature of the server shutdown that would have been fixed in 1.14, but both of them should be fixed now. (LOG4J2-318 also sounds somewhat similar, but that was resolved as fixed in 2.0-beta9, so it wouldn't have affected 1.11.2.)
I see this frequently, also.
stop
[23:35:30] [Server thread/INFO]: Stopping the server
[23:35:30] [Server thread/INFO]: Stopping server
[23:35:30] [Server thread/INFO]: Saving players
[23:35:30] [Server thread/INFO]: Saving worlds
[23:35:30] [Server thread/INFO]: Saving chunks for level '../world'/Overworld
[23:35:30] [Server thread/INFO]: Saving chunks for level '../world'/Nether
[23:35:30] [Server thread/INFO]: Saving chunks for level '../world'/The End
[23:35:32] [Server Shutdown Thread/INFO]: Stopping server
[23:35:32] [Server Shutdown Thread/INFO]: Saving players
[23:35:32] [Server Shutdown Thread/INFO]: Saving worlds
[23:35:32] [Server Shutdown Thread/INFO]: Saving chunks for level '../world'/Overworld
[23:35:32] [Server Shutdown Thread/INFO]: Saving chunks for level '../world'/Nether
2013-11-08 23:35:32,474 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.a(SourceFile:275)
at net.minecraft.server.MinecraftServer.n(SourceFile:297)
at kx.run(SourceFile:605)
$ uname -a
Linux naib 3.11.0-12-generic #19-Ubuntu SMP Wed Oct 9 16:20:46 UTC 2013 x86_64 x86_64 x86_64 GNU/Linux
$ java -version
java version "1.7.0_25"
OpenJDK Runtime Environment (IcedTea 2.3.12) (7u25-2.3.12-4ubuntu3)
OpenJDK 64-Bit Server VM (build 23.7-b01, mixed mode)