[Play 2.4 Java] Logback Dlogger.file override is ignored at beginining in production mode

[michalzubkowicz]

When application is started with parameter ie.
-Dlogger.file=/logback.xml

File is ignored and default one is parsed instead. After application start everything is ok.

[michalzubkowicz]

Jul 15 13:01:54 test myapp-service: 13:01:53,618 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy]
Jul 15 13:01:54 test myapp-service: 13:01:53,619 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
Jul 15 13:01:54 test myapp-service: 13:01:53,619 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [jar:file:/webapps/myappservice5/lib/myapp-service.myapp-service-0.2.jar!/logback.xml]
Jul 15 13:01:54 test myapp-service: 13:01:53,642 |-INFO in ch.qos.logback.core.joran.spi.ConfigurationWatchList@53fb3dab - URL [jar:file:/webapps/myappservice5/lib/myapp-service.myapp-service-0.2.jar!/logback.xml] is not of type file
Jul 15 13:01:54 test myapp-service: 13:01:53,837 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - debug attribute not set
Jul 15 13:01:54 test myapp-service: 13:01:53,840 |-INFO in ch.qos.logback.core.joran.action.ConversionRuleAction - registering conversion word coloredLevel with class [play.api.Logger$ColoredLevel]
Jul 15 13:01:54 test myapp-service: 13:01:53,840 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.FileAppender]
Jul 15 13:01:54 test myapp-service: 13:01:53,852 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [FILE]
Jul 15 13:01:54 test myapp-service: 13:01:53,911 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
Jul 15 13:01:54 test myapp-service: 13:01:54,005 |-INFO in ch.qos.logback.core.FileAppender[FILE] - File property is set to [logs/application.log]
Jul 15 13:01:54 test myapp-service: 13:01:54,009 |-ERROR in ch.qos.logback.core.FileAppender[FILE] - Failed to create parent directories for [/webapps/myappservice5/logs/application.log]
Jul 15 13:01:54 test myapp-service: 13:01:54,010 |-ERROR in ch.qos.logback.core.FileAppender[FILE] - openFile(logs/application.log,true) call failed. java.io.FileNotFoundException: logs/application.log (No such file or directory)
Jul 15 13:01:54 test myapp-service: at java.io.FileNotFoundException: logs/application.log (No such file or directory)
Jul 15 13:01:54 test myapp-service: at  at java.io.FileOutputStream.open0(Native Method)
Jul 15 13:01:54 test myapp-service: at  at java.io.FileOutputStream.open(FileOutputStream.java:270)
Jul 15 13:01:54 test myapp-service: at  at java.io.FileOutputStream.<init>(FileOutputStream.java:213)
Jul 15 13:01:54 test myapp-service: at  at ch.qos.logback.core.recovery.ResilientFileOutputStream.<init>(ResilientFileOutputStream.java:28)
Jul 15 13:01:54 test myapp-service: at  at ch.qos.logback.core.FileAppender.openFile(FileAppender.java:148)
Jul 15 13:01:54 test myapp-service: at  at ch.qos.logback.core.FileAppender.start(FileAppender.java:108)
Jul 15 13:01:54 test myapp-service: at  at ch.qos.logback.core.joran.action.AppenderAction.end(AppenderAction.java:96)
Jul 15 13:01:54 test myapp-service: at  at ch.qos.logback.core.joran.spi.Interpreter.callEndAction(Interpreter.java:317)
Jul 15 13:01:54 test myapp-service: at  at ch.qos.logback.core.joran.spi.Interpreter.endElement(Interpreter.java:196)
Jul 15 13:01:54 test myapp-service: at  at ch.qos.logback.core.joran.spi.Interpreter.endElement(Interpreter.java:182)
Jul 15 13:01:54 test myapp-service: at  at ch.qos.logback.core.joran.spi.EventPlayer.play(EventPlayer.java:62)
Jul 15 13:01:54 test myapp-service: at  at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:149)
Jul 15 13:01:54 test myapp-service: at  at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:135)
Jul 15 13:01:54 test myapp-service: at  at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:99)
Jul 15 13:01:54 test myapp-service: at  at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:49)
Jul 15 13:01:54 test myapp-service: at  at ch.qos.logback.classic.util.ContextInitializer.configureByResource(ContextInitializer.java:77)
Jul 15 13:01:54 test myapp-service: at  at ch.qos.logback.classic.util.ContextInitializer.autoConfig(ContextInitializer.java:152)
Jul 15 13:01:54 test myapp-service: at  at org.slf4j.impl.StaticLoggerBinder.init(StaticLoggerBinder.java:85)
Jul 15 13:01:54 test myapp-service: at  at org.slf4j.impl.StaticLoggerBinder.<clinit>(StaticLoggerBinder.java:55)
Jul 15 13:01:54 test myapp-service: at  at org.slf4j.LoggerFactory.bind(LoggerFactory.java:141)
Jul 15 13:01:54 test myapp-service: at  at org.slf4j.LoggerFactory.performInitialization(LoggerFactory.java:120)
Jul 15 13:01:54 test myapp-service: at  at org.slf4j.LoggerFactory.getILoggerFactory(LoggerFactory.java:331)
Jul 15 13:01:54 test myapp-service: at  at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:283)
Jul 15 13:01:54 test myapp-service: at  at play.api.Logger$.<init>(Logger.scala:177)
Jul 15 13:01:54 test myapp-service: at  at play.api.Logger$.<clinit>(Logger.scala)
Jul 15 13:01:54 test myapp-service: at  at play.api.inject.guice.GuiceApplicationBuilder.applicationModule(GuiceApplicationBuilder.scala:73)
Jul 15 13:01:54 test myapp-service: at  at play.api.inject.guice.GuiceBuilder.injector(GuiceInjectorBuilder.scala:126)
Jul 15 13:01:54 test myapp-service: at  at play.api.inject.guice.GuiceApplicationBuilder.build(GuiceApplicationBuilder.scala:93)
Jul 15 13:01:54 test myapp-service: at  at play.api.inject.guice.GuiceApplicationLoader.load(GuiceApplicationLoader.scala:21)
Jul 15 13:01:54 test myapp-service: at  at play.core.server.ProdServerStart$.start(ProdServerStart.scala:52)
Jul 15 13:01:54 test myapp-service: at  at play.core.server.ProdServerStart$.main(ProdServerStart.scala:27)
Jul 15 13:01:54 test myapp-service: at  at play.core.server.ProdServerStart.main(ProdServerStart.scala)
Jul 15 13:01:54 test myapp-service: 13:01:54,010 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
Jul 15 13:01:54 test myapp-service: 13:01:54,012 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [STDOUT]
Jul 15 13:01:54 test myapp-service: 13:01:54,017 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
Jul 15 13:01:54 test myapp-service: 13:01:54,022 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.classic.AsyncAppender]
Jul 15 13:01:54 test myapp-service: 13:01:54,027 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [ASYNCFILE]
Jul 15 13:01:54 test myapp-service: 13:01:54,027 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [FILE] to ch.qos.logback.classic.AsyncAppender[ASYNCFILE]
Jul 15 13:01:54 test myapp-service: 13:01:54,027 |-INFO in ch.qos.logback.classic.AsyncAppender[ASYNCFILE] - Attaching appender named [FILE] to AsyncAppender.
Jul 15 13:01:54 test myapp-service: 13:01:54,029 |-INFO in ch.qos.logback.classic.AsyncAppender[ASYNCFILE] - Setting discardingThreshold to 51
Jul 15 13:01:54 test myapp-service: 13:01:54,033 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.classic.AsyncAppender]
Jul 15 13:01:54 test myapp-service: 13:01:54,033 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [ASYNCSTDOUT]
Jul 15 13:01:54 test myapp-service: 13:01:54,033 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to ch.qos.logback.classic.AsyncAppender[ASYNCSTDOUT]
Jul 15 13:01:54 test myapp-service: 13:01:54,033 |-INFO in ch.qos.logback.classic.AsyncAppender[ASYNCSTDOUT] - Attaching appender named [STDOUT] to AsyncAppender.
Jul 15 13:01:54 test myapp-service: 13:01:54,033 |-INFO in ch.qos.logback.classic.AsyncAppender[ASYNCSTDOUT] - Setting discardingThreshold to 51
Jul 15 13:01:54 test myapp-service: 13:01:54,034 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [play] to INFO
Jul 15 13:01:54 test myapp-service: 13:01:54,034 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [application] to DEBUG
Jul 15 13:01:54 test myapp-service: 13:01:54,034 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [com.avaje.ebean.config.PropertyMapLoader] to OFF
Jul 15 13:01:54 test myapp-service: 13:01:54,035 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [com.avaje.ebeaninternal.server.core.XmlConfigLoader] to OFF
Jul 15 13:01:54 test myapp-service: 13:01:54,035 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [com.avaje.ebeaninternal.server.lib.BackgroundThread] to OFF
Jul 15 13:01:54 test myapp-service: 13:01:54,035 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [com.gargoylesoftware.htmlunit.javascript] to OFF
Jul 15 13:01:54 test myapp-service: 13:01:54,035 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to WARN
Jul 15 13:01:54 test myapp-service: 13:01:54,035 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [ASYNCFILE] to Logger[ROOT]
Jul 15 13:01:54 test myapp-service: 13:01:54,035 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [ASYNCSTDOUT] to Logger[ROOT]
Jul 15 13:01:54 test myapp-service: 13:01:54,035 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
Jul 15 13:01:54 test myapp-service: 13:01:54,040 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@712625fd - Registering current configuration as safe fallback point
Jul 15 13:01:54 test myapp-service: 13:01:53,618 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy]
Jul 15 13:01:54 test myapp-service: 13:01:53,619 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
Jul 15 13:01:54 test myapp-service: 13:01:53,619 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [jar:file:/webapps/myappservice5/lib/myapp-service.myapp-service-0.2.jar!/logback.xml]
Jul 15 13:01:54 test myapp-service: 13:01:53,642 |-INFO in ch.qos.logback.core.joran.spi.ConfigurationWatchList@53fb3dab - URL [jar:file:/webapps/myappservice5/lib/myapp-service.myapp-service-0.2.jar!/logback.xml] is not of type file
Jul 15 13:01:54 test myapp-service: 13:01:53,837 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - debug attribute not set
Jul 15 13:01:54 test myapp-service: 13:01:53,840 |-INFO in ch.qos.logback.core.joran.action.ConversionRuleAction - registering conversion word coloredLevel with class [play.api.Logger$ColoredLevel]
Jul 15 13:01:54 test myapp-service: 13:01:53,840 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.FileAppender]
Jul 15 13:01:54 test myapp-service: 13:01:53,852 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [FILE]
Jul 15 13:01:54 test myapp-service: 13:01:53,911 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
Jul 15 13:01:54 test myapp-service: 13:01:54,005 |-INFO in ch.qos.logback.core.FileAppender[FILE] - File property is set to [logs/application.log]
Jul 15 13:01:54 test myapp-service: 13:01:54,009 |-ERROR in ch.qos.logback.core.FileAppender[FILE] - Failed to create parent directories for [/webapps/myappservice5/logs/application.log]
Jul 15 13:01:54 test myapp-service: 13:01:54,010 |-ERROR in ch.qos.logback.core.FileAppender[FILE] - openFile(logs/application.log,true) call failed. java.io.FileNotFoundException: logs/application.log (No such file or directory)
Jul 15 13:01:54 test myapp-service: at java.io.FileNotFoundException: logs/application.log (No such file or directory)
Jul 15 13:01:54 test myapp-service: at  at java.io.FileOutputStream.open0(Native Method)
Jul 15 13:01:54 test myapp-service: at  at java.io.FileOutputStream.open(FileOutputStream.java:270)
Jul 15 13:01:54 test myapp-service: at  at java.io.FileOutputStream.<init>(FileOutputStream.java:213)
Jul 15 13:01:54 test myapp-service: at  at ch.qos.logback.core.recovery.ResilientFileOutputStream.<init>(ResilientFileOutputStream.java:28)
Jul 15 13:01:54 test myapp-service: at  at ch.qos.logback.core.FileAppender.openFile(FileAppender.java:148)
Jul 15 13:01:54 test myapp-service: at  at ch.qos.logback.core.FileAppender.start(FileAppender.java:108)
Jul 15 13:01:54 test myapp-service: at  at ch.qos.logback.core.joran.action.AppenderAction.end(AppenderAction.java:96)
Jul 15 13:01:54 test myapp-service: at  at ch.qos.logback.core.joran.spi.Interpreter.callEndAction(Interpreter.java:317)
Jul 15 13:01:54 test myapp-service: at  at ch.qos.logback.core.joran.spi.Interpreter.endElement(Interpreter.java:196)
Jul 15 13:01:54 test myapp-service: at  at ch.qos.logback.core.joran.spi.Interpreter.endElement(Interpreter.java:182)
Jul 15 13:01:54 test myapp-service: at  at ch.qos.logback.core.joran.spi.EventPlayer.play(EventPlayer.java:62)
Jul 15 13:01:54 test myapp-service: at  at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:149)
Jul 15 13:01:54 test myapp-service: at  at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:135)
Jul 15 13:01:54 test myapp-service: at  at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:99)
Jul 15 13:01:54 test myapp-service: at  at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:49)
Jul 15 13:01:54 test myapp-service: at  at ch.qos.logback.classic.util.ContextInitializer.configureByResource(ContextInitializer.java:77)
Jul 15 13:01:54 test myapp-service: at  at ch.qos.logback.classic.util.ContextInitializer.autoConfig(ContextInitializer.java:152)
Jul 15 13:01:54 test myapp-service: at  at org.slf4j.impl.StaticLoggerBinder.init(StaticLoggerBinder.java:85)
Jul 15 13:01:54 test myapp-service: at  at org.slf4j.impl.StaticLoggerBinder.<clinit>(StaticLoggerBinder.java:55)
Jul 15 13:01:54 test myapp-service: at  at org.slf4j.LoggerFactory.bind(LoggerFactory.java:141)
Jul 15 13:01:54 test myapp-service: at  at org.slf4j.LoggerFactory.performInitialization(LoggerFactory.java:120)
Jul 15 13:01:54 test myapp-service: at  at org.slf4j.LoggerFactory.getILoggerFactory(LoggerFactory.java:331)
Jul 15 13:01:54 test myapp-service: at  at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:283)
Jul 15 13:01:54 test myapp-service: at  at play.api.Logger$.<init>(Logger.scala:177)
Jul 15 13:01:54 test myapp-service: at  at play.api.Logger$.<clinit>(Logger.scala)
Jul 15 13:01:54 test myapp-service: at  at play.api.inject.guice.GuiceApplicationBuilder.applicationModule(GuiceApplicationBuilder.scala:73)
Jul 15 13:01:54 test myapp-service: at  at play.api.inject.guice.GuiceBuilder.injector(GuiceInjectorBuilder.scala:126)
Jul 15 13:01:54 test myapp-service: at  at play.api.inject.guice.GuiceApplicationBuilder.build(GuiceApplicationBuilder.scala:93)
Jul 15 13:01:54 test myapp-service: at  at play.api.inject.guice.GuiceApplicationLoader.load(GuiceApplicationLoader.scala:21)
Jul 15 13:01:54 test myapp-service: at  at play.core.server.ProdServerStart$.start(ProdServerStart.scala:52)
Jul 15 13:01:54 test myapp-service: at  at play.core.server.ProdServerStart$.main(ProdServerStart.scala:27)
Jul 15 13:01:54 test myapp-service: at  at play.core.server.ProdServerStart.main(ProdServerStart.scala)
Jul 15 13:01:54 test myapp-service: 13:01:54,010 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
Jul 15 13:01:54 test myapp-service: 13:01:54,012 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [STDOUT]
Jul 15 13:01:54 test myapp-service: 13:01:54,017 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
Jul 15 13:01:54 test myapp-service: 13:01:54,022 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.classic.AsyncAppender]
Jul 15 13:01:54 test myapp-service: 13:01:54,027 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [ASYNCFILE]
Jul 15 13:01:54 test myapp-service: 13:01:54,027 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [FILE] to ch.qos.logback.classic.AsyncAppender[ASYNCFILE]
Jul 15 13:01:54 test myapp-service: 13:01:54,027 |-INFO in ch.qos.logback.classic.AsyncAppender[ASYNCFILE] - Attaching appender named [FILE] to AsyncAppender.
Jul 15 13:01:54 test myapp-service: 13:01:54,029 |-INFO in ch.qos.logback.classic.AsyncAppender[ASYNCFILE] - Setting discardingThreshold to 51
Jul 15 13:01:54 test myapp-service: 13:01:54,033 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.classic.AsyncAppender]
Jul 15 13:01:54 test myapp-service: 13:01:54,033 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [ASYNCSTDOUT]
Jul 15 13:01:54 test myapp-service: 13:01:54,033 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to ch.qos.logback.classic.AsyncAppender[ASYNCSTDOUT]
Jul 15 13:01:54 test myapp-service: 13:01:54,033 |-INFO in ch.qos.logback.classic.AsyncAppender[ASYNCSTDOUT] - Attaching appender named [STDOUT] to AsyncAppender.
Jul 15 13:01:54 test myapp-service: 13:01:54,033 |-INFO in ch.qos.logback.classic.AsyncAppender[ASYNCSTDOUT] - Setting discardingThreshold to 51
Jul 15 13:01:54 test myapp-service: 13:01:54,034 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [play] to INFO
Jul 15 13:01:54 test myapp-service: 13:01:54,034 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [application] to DEBUG
Jul 15 13:01:54 test myapp-service: 13:01:54,034 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [com.avaje.ebean.config.PropertyMapLoader] to OFF
Jul 15 13:01:54 test myapp-service: 13:01:54,035 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [com.avaje.ebeaninternal.server.core.XmlConfigLoader] to OFF
Jul 15 13:01:54 test myapp-service: 13:01:54,035 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [com.avaje.ebeaninternal.server.lib.BackgroundThread] to OFF
Jul 15 13:01:54 test myapp-service: 13:01:54,035 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [com.gargoylesoftware.htmlunit.javascript] to OFF
Jul 15 13:01:54 test myapp-service: 13:01:54,035 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to WARN
Jul 15 13:01:54 test myapp-service: 13:01:54,035 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [ASYNCFILE] to Logger[ROOT]
Jul 15 13:01:54 test myapp-service: 13:01:54,035 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [ASYNCSTDOUT] to Logger[ROOT]
Jul 15 13:01:54 test myapp-service: 13:01:54,035 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
Jul 15 13:01:54 test myapp-service: 13:01:54,040 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@712625fd - Registering current configuration as safe fallback point
Jul 15 13:01:54 test myapp-service: 13:01:54,096 |-INFO in ch.qos.logback.classic.AsyncAppender[ASYNCFILE] - Worker thread will flush remaining events before exiting.
Jul 15 13:01:54 test myapp-service: 13:01:54,097 |-INFO in ch.qos.logback.classic.AsyncAppender[ASYNCFILE] - Queue flush finished successfully within timeout.
Jul 15 13:01:54 test myapp-service: 13:01:54,097 |-INFO in ch.qos.logback.classic.AsyncAppender[ASYNCSTDOUT] - Worker thread will flush remaining events before exiting.
Jul 15 13:01:54 test myapp-service: 13:01:54,097 |-INFO in ch.qos.logback.classic.AsyncAppender[ASYNCSTDOUT] - Queue flush finished successfully within timeout.
Jul 15 13:01:54 test myapp-service: 13:01:54,104 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - debug attribute not set
Jul 15 13:01:54 test myapp-service: 13:01:54,106 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.classic.net.SMTPAppender]
Jul 15 13:01:54 test myapp-service: 13:01:54,122 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [EMAIL]
Jul 15 13:01:54 test myapp-service: 13:01:54,165 |-WARN in Logger[javax.mail] - No appenders present in context [default] for logger [javax.mail].
Jul 15 13:01:54 test myapp-service: 13:01:54,178 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.rolling.RollingFileAppender]
Jul 15 13:01:54 test myapp-service: 13:01:54,179 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [FILE]
Jul 15 13:01:54 test myapp-service: 13:01:54,198 |-INFO in c.q.l.core.rolling.TimeBasedRollingPolicy - Will use gz compression
Jul 15 13:01:54 test myapp-service: 13:01:54,200 |-INFO in c.q.l.core.rolling.TimeBasedRollingPolicy - Will use the pattern myappservice5-%d{yyyy-MM-dd}.log for the active file
Jul 15 13:01:54 test myapp-service: 13:01:54,206 |-INFO in c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - The date pattern is 'yyyy-MM-dd' from file name pattern 'myappservice5-%d{yyyy-MM-dd}.log.gz'.
Jul 15 13:01:54 test myapp-service: 13:01:54,206 |-INFO in c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - Roll-over at midnight.
Jul 15 13:01:54 test myapp-service: 13:01:54,212 |-INFO in c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - Setting initial period to Wed Jul 15 12:47:43 CEST 2015
Jul 15 13:01:54 test myapp-service: 13:01:54,214 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
Jul 15 13:01:54 test myapp-service: 13:01:54,226 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[FILE] - Active log file name: /webapps/myappservice5.log
Jul 15 13:01:54 test myapp-service: 13:01:54,226 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[FILE] - File property is set to [/webapps/myappservice5.log]
Jul 15 13:01:54 test myapp-service: 13:01:54,226 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to DEBUG
Jul 15 13:01:54 test myapp-service: 13:01:54,226 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [FILE] to Logger[ROOT]
Jul 15 13:01:54 test myapp-service: 13:01:54,226 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to ERROR
Jul 15 13:01:54 test myapp-service: 13:01:54,227 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [FILE] to Logger[ROOT]
Jul 15 13:01:54 test myapp-service: 13:01:54,227 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [EMAIL] to Logger[ROOT]
Jul 15 13:01:54 test myapp-service: 13:01:54,227 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
Jul 15 13:01:54 test myapp-service: 13:01:54,227 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@2254127a - Registering current configuration as safe fallback point
Jul 15 13:02:37 test myapp-service: Wed Jul 15 13:02:37 CEST 2015 [WARN] CredentialStore: Using no-op credential store. Not persisting credentials! If you want to persist authentication, please use a custom implementation of CredentialStore.

[avdv]

Confirming.

Logback actually loads either the logback.groovy, logback-test.xml or logback.xml file on its own, if it sees one of them in the classpath.

When the application starts, Play comes into play, resets the logging configuration and configures the logging on its own.

Currently, the main problem for me with that approach is that Play overwrites my logback-test.xml which I want to use during test runs, with what it thinks is better suited. This results in ClassNotFoundException's for classes referenced in the logback.xml file.

@michalzubkowicz Resorting to the legacy approach of calling the logfile logger.xml should resolve your problem in the meantime. Make sure you don't have any other logback*.{xml,groovy} in your classpath.

Since application-logger.xml is preferred over logger.xml I'm going to use the former as my "logback-test.xml" file. But this is awful...

[rmmeans]

I can also confim this -- if you use any other file name than the default name (i.e. logger.xml), it won't load. I had a custom file in my conf directory, if I named it logger.xml it would pick it up, if I named it logger2.xml and passed in an argument such as -Dlogger.resource=logback2.xml it wouldn't load the file and fell back to the original.

[rmmeans]

I'm backing out my claim that I can confirm this. I was having problems getting other log settings to load, but only when I was doing compile time DI in Scala. I have PR coming in to fix that - for runtime DI, this should not have been a problem. I was able to load resources by any file name located in any folder on my box via -Dlogger.file=...

[michalzubkowicz]

Changing the name of default log file in classpath helped me. Now it's loading the one from parameter

[wsargent]

The beginning lines are

Jul 15 13:01:54 test myapp-service: 13:01:53,618 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy]
Jul 15 13:01:54 test myapp-service: 13:01:53,619 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
Jul 15 13:01:54 test myapp-service: 13:01:53,619 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [jar:file:/webapps/myappservice5/lib/myapp-service.myapp-service-0.2.jar!/logback.xml]

This info text is displayed by Logback when there's a problem with the logger configuration -- I'd need to see the config for this to reproduce it.

[wsargent]

Changing the name of default log file in classpath helped me. Now it's loading the one from parameter

Two files called logback.xml in the classpath will cause the error displayed above, so that explains it. Closing.

[maxharp3r]

I think this should be reopened, and I can add additional info on how to recreate. It does not have anything to do with two files called logback.xml in our case, @wsargent .

It affects us in Play 2.5 production mode, where we are using system properties to (attempt to) override the default logback config file path. As described by @avdv, logback appears to be configured twice - the first pass spews debugging info in our case if we include an SMTPAppender. If there is no SMTPAppender, the log messages indicating problems disappear.

The workaround we are using is to delete logback.xml as part of our deployment process.

[avdv]

Yes, abusing logback.xml as default file for Play was a bad idea, IMO. It breaks logback's default config file handling because Play wants to have the last word on how to configure the logging.

What we do to work around that is, we have a second logback config file which is configured as logback's default config file using -Dlogback.configurationFile=/path/to/logback-base.xml. That config defines a basic appender (logging to the syslog) which is only used until Play re-configures the logging by itself.

[KarelCemus]

I faced a similar issue with annoying unformatted info messages before my logback.xml was properly parsed and I found a workaround here.

Shortly and in case the link will die, add this into logback.xml and the info messages in a preamble goes away.

    <!-- Stop output INFO at start -->
    <statusListener class="ch.qos.logback.core.status.NopStatusListener" />