[MC-38134] Race condition in logging when shutting down

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

MC-45051 ERROR Attempted to append to non-started appender ServerGuiConsole

MC-52794 Error on server close (1.7.7 & 1.7.8)

MC-54408 Server throws exceptions after stopping

MC-61477 Server crashes when stopped before EULA agreed to

MC-73537 Error appears when executing /stop from server console command line

MC-78246 Error Message when Closing Vanilla Server 1.8.1

MC-89286 I can't get in to minecraft.

MC-89287 Logging errors when shutting down Minecraft server

MC-98879 ERROR Attempted to append to non-started appender File - Server Minecraft 1.9

MC-100422 Headless server shutdown AppenderLoggingException

MC-101810 Server Error On Shutdown: 670 ERROR Attempted to append to non-started appender File

MC-106120 I cant start my minecraft server

Comments

Mark Fickett 2013-11-09T04:55:47Z

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)

Olle Kelderman 2013-11-12T23:22:09Z

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...

wojtekpod 2013-12-08T11:52:15Z

I see the problem also in 1.7.3 server.

Branko 2013-12-21T19:12:45Z

Can confirm on 1.7.4 server. (Win XP, Java 7 U45)

Victor N 2014-01-24T17:53:24Z

Duplicated by MC-45051.
Please add 14w03b to Affected Versions.

Victor N 2014-01-24T18:27:13Z

Affects 14w04a.

Additional information:
If the server is stopped during the first two seconds after entering The End dimension for the first time on the server, the spawn platform is not saved to disk, and the "ERROR Attempted to append to non-started appender ServerGuiConsole" message is thrown.

David Cady 2014-03-02T19:33:40Z

All snapshots up to 14w08a are afflicted with this bug.

Jack Walsh 2014-03-16T20:41:01Z

Can confirm for 1.7.5 server, (Mac OS X 10.9.2, Java Version 7 Update 51)

David Wheatley 2014-04-12T07:19:30Z

Confirmed for 1.7.6, 1.7.7 and 1.7.8 with Java 7 as well.

Branko 2014-04-12T10:28:08Z

Confirming for 1.7.8 on Win7 SP1, Java 1.8.0-b132.

Christopher Chin 2014-08-29T01:24:40Z

Confirming for Minecraft server version 1.8-pre3. http://pastebin.com/7DxHyTHY Java build 1.8.0-b132

Michael Grey 2014-09-01T15:46:31Z

Adding to 1.8-pre3. No one on server but moments before, (15 seconds or so) the last user exited the game. - Linux Centos 6.5 / Java 1.7.0_55 64bit

- PLEASE NOTE ** this happened SPONTANEOUSLY - not as a result of intentionally trying to shut down the server or any player action.

[22:24:42] [Server Shutdown Thread/INFO]: Stopping server
2014-08-31 22:24:42,719 ERROR Attempted to append to non-started appender SysOut
[22:24:42] [Server Shutdown Thread/INFO]: Saving players
2014-08-31 22:24:42,719 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.r(SourceFile:377)
at pe.run(SourceFile:715)

Anthoni Wiese 2015-01-01T06:40:00Z

Can confirm for 1.8.1

André-Marcel Julius 2015-04-01T12:28:03Z

Can confirm for MC 1.8.3 running on
Debian 3.2.65-1+deb7u2 i686 GNU/Linux and using
java version "1.6.0_34"
OpenJDK Runtime Environment (IcedTea6 1.13.6) (6b34-1.13.6-1~deb7u1)
OpenJDK Server VM (build 23.25-b01, mixed mode).

Philip Jagielski 2015-04-24T04:54:04Z

Can confirm for MC 1.8.4

$ java -version
java version "1.7.0_75"
OpenJDK Runtime Environment (amzn-2.5.4.0.53.amzn1-x86_64 u75-b13)
OpenJDK 64-Bit Server VM (build 24.75-b04, mixed mode)

Tom van Leeuwen 2015-06-12T05:36:10Z

Can confirm for MC 1.8.7 running on
Ubuntu 14.04.2 LTS
$ java -version
java version "1.7.0_79"
OpenJDK Runtime Environment (IcedTea 2.5.5) (7u79-2.5.5-0ubuntu0.14.04.2)
OpenJDK 64-Bit Server VM (build 24.79-b02, mixed mode)

$ cat minecraft.sh
#!/bin/bash
cd "$(dirname "$0")"
exec java -Xmx2048M -Xms1024M -d64 -jar minecraft_server.jar nogui

MC output

$ ./minecraft.sh
[07:20:55] [Server thread/INFO]: Starting minecraft server version 1.8.7
[07:20:55] [Server thread/INFO]: Loading properties
[07:20:55] [Server thread/INFO]: Default game type: SURVIVAL
[07:20:55] [Server thread/INFO]: Generating keypair
[07:20:56] [Server thread/INFO]: Starting Minecraft server on *:25565
[07:20:56] [Server thread/INFO]: Using epoll channel type
[07:20:56] [Server thread/INFO]: Preparing level "world"
[07:20:56] [Server thread/INFO]: Preparing start region for level 0
[07:20:57] [Server thread/INFO]: Preparing spawn area: 63%
[07:20:57] [Server thread/INFO]: Done (1.353s)! For help, type "help" or "?"
stop
[07:30:58] [Server thread/INFO]: Stopping the server
[07:30:58] [Server thread/INFO]: Stopping server
[07:30:58] [Server thread/INFO]: Saving players
[07:30:58] [Server thread/INFO]: Saving worlds
[07:30:58] [Server thread/INFO]: Saving chunks for level 'world'/Overworld
[07:30:58] [Server thread/INFO]: Saving chunks for level 'world'/Nether
[07:30:58] [Server thread/INFO]: Saving chunks for level 'world'/The End
[07:30:58] [Server Shutdown Thread/INFO]: Stopping server
[07:30:58] [Server Shutdown Thread/INFO]: Saving players
2015-06-12 07:30:58,309 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.t(SourceFile:381)
        at net.minecraft.server.MinecraftServer$2.run(SourceFile:715)

Jeff Bowman 2015-08-05T00:40:47Z

Confirmed in 15w31c as well.

I think this bug should be marked as critical, because if you look at what's occurring in the code, it very much appears that the method is throwing the exception before it saves player or world data.

When the server shuts down normally then it's less of an issue because it also saves earlier in the shutdown process. But if a crash occurred elsewhere, this is supposed to be the last resort to preventing data loss, and yet it's crashing as well.

Cy-V 2015-09-09T15:33:52Z

Confirmed in 1.8.8 as well.

09.09 07:00:23 [Server] Startup Done (15.717s)! For help, type "help" or "?"
09.09 07:00:23 [Server] Server thread/INFO Preparing spawn area: 60%
09.09 07:00:22 [Server] Server thread/INFO Preparing spawn area: 0%
09.09 07:00:07 [Server] Server thread/INFO Preparing start region for level 0
09.09 07:00:07 [Server] Server thread/INFO Preparing level "world"
09.09 07:00:07 [Server] Server thread/INFO Using epoll channel type
09.09 07:00:07 [Server] Server thread/INFO Starting Minecraft server on *:25991
09.09 07:00:07 [Server] Server thread/INFO Generating keypair
09.09 07:00:07 [Server] Server thread/INFO Default game type: SURVIVAL
09.09 07:00:07 [Server] Server thread/INFO Loading properties
09.09 07:00:07 [Server] Server thread/INFO Starting minecraft server version 1.8.8
09.09 07:00:00 [Multicraft] Loaded config for "Vanilla Minecraft"
09.09 07:00:00 [Multicraft] Starting server!
09.09 07:00:00 [Multicraft] Loading server properties
09.09 07:00:00 [Multicraft] Server stopped
09.09 07:00:00 [Multicraft] Server shut down
09.09 07:00:00 [Server] INFO at net.minecraft.server.MinecraftServer$2.run(SourceFile:715)
09.09 07:00:00 [Server] INFO at net.minecraft.server.MinecraftServer.t(SourceFile:387)
09.09 07:00:00 [Server] INFO at net.minecraft.server.MinecraftServer.a(SourceFile:361)
09.09 07:00:00 [Server] INFO at org.apache.logging.log4j.spi.AbstractLogger.info(AbstractLogger.java:1011)
09.09 07:00:00 [Server] INFO at org.apache.logging.log4j.core.Logger.log(Logger.java:110)
09.09 07:00:00 [Server] INFO at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:367)
09.09 07:00:00 [Server] INFO at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:406)
09.09 07:00:00 [Server] INFO at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:425)
09.09 07:00:00 [Server] INFO at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:89)
09.09 07:00:00 [Server] INFO Exception in thread "Server Shutdown Thread" org.apache.logging.log4j.core.appender.AppenderLoggingException: Attempted to append to non-started appender ServerGuiConsole
09.09 07:00:00 [Server] INFO 2015-09-09 07:00:00,396 ERROR Attempted to append to non-started appender ServerGuiConsole
09.09 07:00:00 [Server] Server Shutdown Thread/INFO Saving chunks for level 'world'/Overworld
09.09 07:00:00 [Server] Server Shutdown Thread/INFO Saving worlds
09.09 07:00:00 [Server] Server Shutdown Thread/INFO Saving players
09.09 07:00:00 [Server] Server Shutdown Thread/INFO Stopping server
09.09 07:00:00 [Server] Server thread/INFO Saving chunks for level 'world'/The End
09.09 07:00:00 [Server] Server thread/INFO Saving chunks for level 'world'/Nether
09.09 07:00:00 [Server] Server thread/INFO Saving chunks for level 'world'/Overworld
09.09 07:00:00 [Server] Server thread/INFO Saving worlds
09.09 07:00:00 [Server] Server thread/INFO Saving players
09.09 07:00:00 [Server] Server thread/INFO Stopping server
09.09 07:00:00 [Server] Server thread/INFO Stopping the server
09.09 07:00:00 [Server] Server thread/INFO Saving...
09.09 07:00:00 [Multicraft] Server ran command Restart
09.09 07:00:00 [Multicraft] Stopping server!
09.09 06:59:00 [Server] Server thread/INFO §8World saved.
09.09 06:59:00 [Server] Server thread/INFO Saving...
09.09 06:59:00 [Multicraft] Server ran command Admin Say
09.09 06:59:00 [Multicraft] Server ran command Save World
09.09 06:57:00 [Multicraft] Server ran command Admin Say
09.09 06:50:00 [Multicraft] Server ran command Admin Say

Colin Smith 2015-10-15T05:16:57Z

Confirmed, still happens in 15w42a

Someone 3x7 2015-12-09T15:41:04Z

This is still corrupting my worlds in 15w49b.

Jordan Cole 2016-02-11T00:14:32Z

confirmed in 1.8.9 except that my issue is every time the server shuts down

[17:53:22] [Server thread/INFO]: Starting minecraft server version 1.8.9
[17:53:22] [Server thread/INFO]: Loading properties
[17:53:22] [Server thread/INFO]: Default game type: SURVIVAL
[17:53:22] [Server thread/INFO]: Generating keypair
[17:53:22] [Server thread/INFO]: Starting Minecraft server on *:25565
[17:53:22] [Server thread/INFO]: Using default channel type
[17:53:22] [Server thread/INFO]: Preparing level "world"
[17:53:22] [Server thread/INFO]: Preparing start region for level 0
[17:53:23] [Server thread/INFO]: Done (1.109s)! For help, type "help" or "?"
stop
[17:55:28] [Server thread/INFO]: Stopping the server
[17:55:28] [Server thread/INFO]: Stopping server
[17:55:28] [Server thread/INFO]: Saving players
[17:55:28] [Server thread/INFO]: Saving worlds
[17:55:28] [Server thread/INFO]: Saving chunks for level 'world'/Overworld
[17:55:28] [Server thread/INFO]: Saving chunks for level 'world'/Nether
[17:55:28] [Server thread/INFO]: Saving chunks for level 'world'/The End
[17:55:28] [Server Shutdown Thread/INFO]: Stopping server
2016-02-10 17:55:28,393 ERROR Attempted to append to non-started appender File
2016-02-10 17:55:28,398 ERROR Unable to write to stream logs/latest.log for appender File
2016-02-10 17:55:28,405 ERROR An exception occurred processing Appender File org.apache.logging.log4j.core.appender.AppenderLoggingException: Error writing to RandomAccessFile logs/latest.log
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.flush(RollingRandomAccessFileManager.java:109)
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.write(RollingRandomAccessFileManager.java:90)
at org.apache.logging.log4j.core.appender.OutputStreamManager.write(OutputStreamManager.java:129)
at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:113)
at org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:96)
at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:99)
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.t(SourceFile:376)
at net.minecraft.server.MinecraftServer$2.run(SourceFile:715)
Caused by: java.io.IOException: Stream Closed
at java.io.RandomAccessFile.writeBytes(Native Method)
at java.io.RandomAccessFile.write(Unknown Source)
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.flush(RollingRandomAccessFileManager.java:106)
... 12 more

2016-02-10 17:55:28,449 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.t(SourceFile:376)
at net.minecraft.server.MinecraftServer$2.run(SourceFile:715)

Megabobster 2016-06-17T00:12:22Z

Confirmed present in 1.10.

marcono1234 2016-08-30T16:23:34Z

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.

marcono1234 2016-09-01T10:32:53Z

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.

wobst.michael 2020-02-16T09:28:16Z

Can someone please check, if this still applies to 1.15.2 or the latest 1.16 development snapshot (currently that is 20w07a)?

pokechu22 2020-02-17T00:10:50Z

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 players

The "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 saved

Note 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))

pokechu22 2020-02-17T01:36:27Z

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.)