No output in log file using Log4j and slf4j

Question

Question I don't get any output to the Gamebot.log file, but I do get it on the console and I have no idea why it doesn't output to the log. Please help.

The code
Log4j config file

 <?xml version="1.0" encoding="UTF-8"?>
 <Configuration status="DEBUG" name="GameBot">
 <Appenders>
 <Console name="Console" target="SYSTEM_OUT">
 <PatternLayout pattern="%d{HH:mm:ss.SSS} [%-5level] %logger{36} - %msg%n" />
 </Console>
 <File name="MyFile" fileName="Gamebot.log" immediateFlush="false" append="false">
 <PatternLayout pattern="%d{yyy-MM-dd HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/>
 </File>
 </Appenders>
 <Loggers>
 <Root level="DEBUG">
 <AppenderRef ref="MyFile" />
 </Root>
 <Root level="INFO">
 <AppenderRef ref="Console" />
 </Root>
 <Logger name="wh1spr.gamebot.MessageHandler" level="Debug" additivity="false">
 <AppenderRef ref="Console" />
 </Logger>
 </Loggers>
 </Configuration>

The code itself

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
public class MessageHandler {
 final static Logger logger = LoggerFactory.getLogger(MessageHandler.class);
 ...
 @EventSubscriber
 public onMessageReceived(MessageReceivedEvent event) {
 ...
 logger.info("This should show up in both console and Gamebot.log")
 ...
 }
 ...
}

The output
For the file, nothing.
For the console: Logging bot in...

2017年05月30日 17:54:54,666 main DEBUG Initializing configuration XmlConfiguration[location=/Users/NAME/Desktop/Workspace/DiscordBot/bin/log4j2.xml]
2017年05月30日 17:54:54,675 main DEBUG Installed script engines
2017年05月30日 17:54:55,164 main DEBUG Oracle Nashorn Version: 1.8.0_45, Language: ECMAScript, Threading: Not Thread Safe, Compile: true, Names: {nashorn, Nashorn, js, JS, JavaScript, javascript, ECMAScript, ecmascript}
2017年05月30日 17:54:55,164 main DEBUG PluginManager 'Core' found 112 plugins
2017年05月30日 17:54:55,165 main DEBUG PluginManager 'Level' found 0 plugins
2017年05月30日 17:54:55,170 main DEBUG PluginManager 'Lookup' found 13 plugins
2017年05月30日 17:54:55,173 main DEBUG Building Plugin[name=layout, class=org.apache.logging.log4j.core.layout.PatternLayout].
2017年05月30日 17:54:55,188 main DEBUG PluginManager 'TypeConverter' found 26 plugins
2017年05月30日 17:54:55,201 main DEBUG PatternLayout$Builder(pattern="%d{HH:mm:ss.SSS} [%-5level] %logger{36} - %msg%n", PatternSelector=null, Configuration(GameBot), Replace=null, charset="null", alwaysWriteExceptions="null", disableAnsi="null", noConsoleNoAnsi="null", header="null", footer="null")
2017年05月30日 17:54:55,201 main DEBUG PluginManager 'Converter' found 41 plugins
2017年05月30日 17:54:55,202 main DEBUG Building Plugin[name=appender, class=org.apache.logging.log4j.core.appender.ConsoleAppender].
2017年05月30日 17:54:55,210 main DEBUG ConsoleAppender$Builder(target="SYSTEM_OUT", follow="null", direct="null", bufferedIo="null", bufferSize="null", immediateFlush="null", ignoreExceptions="null", PatternLayout(%d{HH:mm:ss.SSS} [%-5level] %logger{36} - %msg%n), name="Console", Configuration(GameBot), Filter=null)
2017年05月30日 17:54:55,210 main DEBUG Starting OutputStreamManager SYSTEM_OUT.false.false
2017年05月30日 17:54:55,211 main DEBUG Building Plugin[name=layout, class=org.apache.logging.log4j.core.layout.PatternLayout].
2017年05月30日 17:54:55,212 main DEBUG PatternLayout$Builder(pattern="%d{yyy-MM-dd HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n", PatternSelector=null, Configuration(GameBot), Replace=null, charset="null", alwaysWriteExceptions="null", disableAnsi="null", noConsoleNoAnsi="null", header="null", footer="null")
2017年05月30日 17:54:55,225 main DEBUG Building Plugin[name=appender, class=org.apache.logging.log4j.core.appender.FileAppender].
2017年05月30日 17:54:55,230 main DEBUG FileAppender$Builder(fileName="Gamebot.log", append="false", locking="null", advertise="null", advertiseUri="null", createOnDemand="null", bufferedIo="null", bufferSize="null", immediateFlush="false", ignoreExceptions="null", PatternLayout(%d{yyy-MM-dd HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n), name="MyFile", Configuration(GameBot), Filter=null)
2017年05月30日 17:54:55,233 main DEBUG Starting FileManager Gamebot.log
2017年05月30日 17:54:55,234 main DEBUG Building Plugin[name=appenders, class=org.apache.logging.log4j.core.config.AppendersPlugin].
2017年05月30日 17:54:55,235 main DEBUG createAppenders(={Console, MyFile})
2017年05月30日 17:54:55,235 main DEBUG Building Plugin[name=AppenderRef, class=org.apache.logging.log4j.core.config.AppenderRef].
2017年05月30日 17:54:55,243 main DEBUG createAppenderRef(ref="MyFile", level="null", Filter=null)
2017年05月30日 17:54:55,244 main DEBUG Building Plugin[name=root, class=org.apache.logging.log4j.core.config.LoggerConfig$RootLogger].
2017年05月30日 17:54:55,245 main DEBUG createLogger(additivity="null", level="DEBUG", includeLocation="null", ={MyFile}, ={}, Configuration(GameBot), Filter=null)
2017年05月30日 17:54:55,248 main DEBUG Building Plugin[name=AppenderRef, class=org.apache.logging.log4j.core.config.AppenderRef].
2017年05月30日 17:54:55,249 main DEBUG createAppenderRef(ref="Console", level="null", Filter=null)
2017年05月30日 17:54:55,249 main DEBUG Building Plugin[name=root, class=org.apache.logging.log4j.core.config.LoggerConfig$RootLogger].
2017年05月30日 17:54:55,250 main DEBUG createLogger(additivity="null", level="INFO", includeLocation="null", ={Console}, ={}, Configuration(GameBot), Filter=null)
2017年05月30日 17:54:55,251 main DEBUG Building Plugin[name=AppenderRef, class=org.apache.logging.log4j.core.config.AppenderRef].
2017年05月30日 17:54:55,251 main DEBUG createAppenderRef(ref="Console", level="null", Filter=null)
2017年05月30日 17:54:55,252 main DEBUG Building Plugin[name=logger, class=org.apache.logging.log4j.core.config.LoggerConfig].
2017年05月30日 17:54:55,256 main DEBUG createLogger(additivity="false", level="DEBUG", name="wh1spr.gamebot.MessageHandler", includeLocation="null", ={Console}, ={}, Configuration(GameBot), Filter=null)
2017年05月30日 17:54:55,257 main DEBUG Building Plugin[name=loggers, class=org.apache.logging.log4j.core.config.LoggersPlugin].
2017年05月30日 17:54:55,258 main DEBUG createLoggers(={root, root, wh1spr.gamebot.MessageHandler})
2017年05月30日 17:54:55,259 main DEBUG Configuration XmlConfiguration[location=/Users/NAME/Desktop/Workspace/DiscordBot/bin/log4j2.xml] initialized
2017年05月30日 17:54:55,260 main DEBUG Starting configuration XmlConfiguration[location=/Users/NAME/Desktop/Workspace/DiscordBot/bin/log4j2.xml]
2017年05月30日 17:54:55,260 main DEBUG Started configuration XmlConfiguration[location=/Users/NAME/Desktop/Workspace/DiscordBot/bin/log4j2.xml] OK.
2017年05月30日 17:54:55,263 main DEBUG Shutting down OutputStreamManager SYSTEM_OUT.false.false-1
2017年05月30日 17:54:55,263 main DEBUG Shut down OutputStreamManager SYSTEM_OUT.false.false-1, all resources released: true
2017年05月30日 17:54:55,263 main DEBUG Appender DefaultConsole-1 stopped with status true
2017年05月30日 17:54:55,264 main DEBUG Stopped org.apache.logging.log4j.core.config.DefaultConfiguration@58d25a40 OK
2017年05月30日 17:54:55,325 main DEBUG Registering MBean org.apache.logging.log4j2:type=73d16e93
2017年05月30日 17:54:55,327 main DEBUG Registering MBean org.apache.logging.log4j2:type=73d16e93,component=StatusLogger
2017年05月30日 17:54:55,329 main DEBUG Registering MBean org.apache.logging.log4j2:type=73d16e93,component=ContextSelector
2017年05月30日 17:54:55,331 main DEBUG Registering MBean org.apache.logging.log4j2:type=73d16e93,component=Loggers,name=
2017年05月30日 17:54:55,332 main DEBUG Registering MBean org.apache.logging.log4j2:type=73d16e93,component=Loggers,name=wh1spr.gamebot.MessageHandler
2017年05月30日 17:54:55,336 main DEBUG Registering MBean org.apache.logging.log4j2:type=73d16e93,component=Appenders,name=Console
2017年05月30日 17:54:55,337 main DEBUG Registering MBean org.apache.logging.log4j2:type=73d16e93,component=Appenders,name=MyFile
2017年05月30日 17:54:55,338 main DEBUG Reconfiguration complete for context[name=73d16e93] at URI /Users/NAME/Desktop/Workspace/DiscordBot/bin/log4j2.xml (org.apache.logging.log4j.core.LoggerContext@2cdd0d4b) with optional ClassLoader: null
2017年05月30日 17:54:55,339 main DEBUG Shutdown hook enabled. Registering a new one.
2017年05月30日 17:54:55,340 main DEBUG LoggerContext[name=73d16e93, org.apache.logging.log4j.core.LoggerContext@2cdd0d4b] started OK.
17:54:55.383 [INFO ] org.eclipse.jetty.util.log - Logging initialized @1179ms to org.eclipse.jetty.util.log.Slf4jLog
17:54:55.389 [INFO ] sx.blah.discord.Discord4J - Discord4J v2.8.1 (60523841852316689438ed3099ad7203f5bd262b-6052384) (https://github.com/austinv11/Discord4J)
17:54:55.389 [INFO ] sx.blah.discord.Discord4J - A Java binding for the official Discord API, forked from the inactive https://github.com/nerd/Discord4J. Copyright (c) 2017, Licensed under GNU LGPLv3
17:54:56.887 [INFO ] sx.blah.discord.Discord4J - Websocket Connected.
17:54:57.107 [INFO ] sx.blah.discord.Discord4J - Connected to Discord Gateway v5. Receiving 1 guilds.
GameBot is ready for action!
17:55:19.565 [DEBUG] wh1spr.gamebot.MessageHandler - Message received! Wh1spr > &&shutdown ==> This is the message that initiates shutdown (saving a few files then calling System.exit(0))
2017年05月30日 17:55:19,740 pool-1-thread-1 DEBUG Stopping LoggerContext[name=73d16e93, org.apache.logging.log4j.core.LoggerContext@2cdd0d4b]
2017年05月30日 17:55:19,740 pool-1-thread-1 DEBUG Stopping LoggerContext[name=73d16e93, org.apache.logging.log4j.core.LoggerContext@2cdd0d4b]...
2017年05月30日 17:55:19,743 pool-1-thread-1 DEBUG Shutting down FileManager Gamebot.log
2017年05月30日 17:55:19,744 pool-1-thread-1 DEBUG Shut down FileManager Gamebot.log, all resources released: true ==> It should've written something to the file here, yet it doesn't.
2017年05月30日 17:55:19,744 pool-1-thread-1 DEBUG Appender MyFile stopped with status true
2017年05月30日 17:55:19,744 pool-1-thread-1 DEBUG Shutting down OutputStreamManager SYSTEM_OUT.false.false
2017年05月30日 17:55:19,744 pool-1-thread-1 DEBUG Shut down OutputStreamManager SYSTEM_OUT.false.false, all resources released: true
2017年05月30日 17:55:19,745 pool-1-thread-1 DEBUG Appender Console stopped with status true
2017年05月30日 17:55:19,745 pool-1-thread-1 DEBUG Stopped XmlConfiguration[location=/Users/NAME/Desktop/Workspace/DiscordBot/bin/log4j2.xml] OK
2017年05月30日 17:55:19,745 pool-1-thread-1 DEBUG Stopped LoggerContext[name=73d16e93, org.apache.logging.log4j.core.LoggerContext@2cdd0d4b] with status true

EDIT:
The imported libraries are

• log4j-api-2.8.2.jar
• log4j-core-2.8.2.jar
• log4j-slf4j-impl-2.8.2.jar
• slf4j-api-1.7.25.jar

• Ishnark: Have you tried replacing <File>...</File> with <RollingFile>...</RollingFile> in your xml
• Wh1spr: This gives me an error "Arguments given for element RollingFile are invalid" It is an "ConfigurationException"

Answer 1

This ended up being longer than a comment, so I'll post it as an answer.

1. your File Appender seems to be correct.

2. It looks like you can only set the Root level once. So what you're actually telling log4j is something like this:

   i. "Set the root logger's level to be debug, and have it use the File appender called 'MyFile'.

   ii. But then you say, "Actually, set the root logger's level to be info, and have the appender be the Console appender called 'Console'.

3. What you were doing with the logger you defined, when you do the following:

   <Logger name="wh1spr.gamebot.MessageHandler" level="Debug" additivity="false">
    <AppenderRef ref="Console" />
   </Logger>
   

   tells log4j that you want to create a Logger called "wh1spr.gamebot.MessageHandler" with level set to debug, and you want it to use the Appender called Console'. Now, since you've set the root logger's level toINFO`, your current logger's level is Debug (which is higher precedence), so you just use the console appender.

You should be able to fix this by getting rid of the second <Root>...</Root>