Hello all
From my searches about how to configure logback logging with custom properties inside the logback.xml I have been able to deduce that the following setup should normally work:
[part of logback.xml]
<appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
<file>${logging.file.name}</file>
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<fileNamePattern>${logging.file.pattern}</fileNamePattern>
</rollingPolicy>
<encoder>
<pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %c{1} - %msg%n</pattern>
</encoder>
</appender>
And configuration:
play.logger.includeConfigProperties = true
logging.file.name = "file_service_appl.log"
logging.file.pattern = "file_service_appl.%d{yyyy-MM-dd}.log"
And context initialization:
ApplicationLoader.Context context = ApplicationLoader.create(environment.asJava(), additionalConfig);
ApplicationLoader loader = ApplicationLoader.apply(context);
return loader.load(context).asScala();
The properties above are in additionalConfig (obtained externally)
Now this is more or less true, the correct files are created and the rolling pattern is being active. However there is an exception printed when my application is starting while bootstraping the logback context:
13:01:56,860 |-ERROR in ch.qos.logback.core.joran.spi.Interpreter@19:25 - RuntimeException in Action for tag [rollingPolicy] java.lang.IllegalStateException: FileNamePattern [logging.file.pattern_IS_UNDEFINED] does not contain a valid DateToken
at java.lang.IllegalStateException: FileNamePattern [logging.file.pattern_IS_UNDEFINED] does not contain a valid DateToken
at at ch.qos.logback.core.rolling.TimeBasedFileNamingAndTriggeringPolicyBase.start(TimeBasedFileNamingAndTriggeringPolicyBase.java:52)
at at ch.qos.logback.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy.start(DefaultTimeBasedFileNamingAndTriggeringPolicy.java:33)
at at ch.qos.logback.core.rolling.TimeBasedRollingPolicy.start(TimeBasedRollingPolicy.java:95)
at at ch.qos.logback.core.joran.action.NestedComplexPropertyIA.end(NestedComplexPropertyIA.java:161)
at at ch.qos.logback.core.joran.spi.Interpreter.callEndAction(Interpreter.java:309)
at at ch.qos.logback.core.joran.spi.Interpreter.endElement(Interpreter.java:193)
at at ch.qos.logback.core.joran.spi.Interpreter.endElement(Interpreter.java:179)
at at ch.qos.logback.core.joran.spi.EventPlayer.play(EventPlayer.java:62)
at at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:165)
at at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:152)
at at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:110)
at at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:53)
at at ch.qos.logback.classic.util.ContextInitializer.configureByResource(ContextInitializer.java:75)
at at ch.qos.logback.classic.util.ContextInitializer.autoConfig(ContextInitializer.java:150)
at at org.slf4j.impl.StaticLoggerBinder.init(StaticLoggerBinder.java:84)
at at org.slf4j.impl.StaticLoggerBinder.<clinit>(StaticLoggerBinder.java:55)
at at org.slf4j.LoggerFactory.bind(LoggerFactory.java:150)
at at org.slf4j.LoggerFactory.performInitialization(LoggerFactory.java:124)
at at org.slf4j.LoggerFactory.getILoggerFactory(LoggerFactory.java:412)
at at com.lightbend.lagom.internal.logback.LogbackLoggerConfigurator.configure(LogbackLoggerConfigurator.scala:95)
at at com.lightbend.lagom.internal.logback.LogbackLoggerConfigurator.configure(LogbackLoggerConfigurator.scala:66)
at at play.api.inject.guice.GuiceApplicationBuilder.$anonfun$configureLoggerFactory$1(GuiceApplicationBuilder.scala:124)
at at scala.Option.map(Option.scala:146)
at at play.api.inject.guice.GuiceApplicationBuilder.configureLoggerFactory(GuiceApplicationBuilder.scala:123)
at at play.api.inject.guice.GuiceApplicationBuilder.applicationModule(GuiceApplicationBuilder.scala:101)
at at play.api.inject.guice.GuiceBuilder.injector(GuiceInjectorBuilder.scala:186)
at at play.api.inject.guice.GuiceApplicationBuilder.build(GuiceApplicationBuilder.scala:139)
at at play.api.inject.guice.GuiceApplicationLoader.load(GuiceApplicationLoader.scala:21)
at at play.ApplicationLoader$1.load(ApplicationLoader.java:44)
The error indicates, that there is at least one logger attempted to be created that does not have the properties it needs. The reason can be found her (think ):
com.lightbend.lagom.internal.logback.LogbackLoggerConfigurator.configure(LogbackLoggerConfigurator.scala:95)
val ctx = LoggerFactory.getILoggerFactory.asInstanceOf[LoggerContext]
val configurator = new JoranConfigurator
configurator.setContext(ctx)
ctx.reset()
// .....
properties.foreach {
case (name, value) => ctx.putProperty(name, value)
}
The LoggerFactory.getILoggerFactory will already create a logger and bootstrap all the logback.xml parsing, but the properties will be set much later.
So while this is functionally not creating an issue for the loggers created later it creates this nasty exception in the stack trace. My solution was to provide a default value in the logback.xml but I do not like it. For example the last deployment I forgot to setup the logging configuration in the properties, however there was no issue starting it because the default values kicked in and the log was created where I didnt want it.
As I am writing my question I am no longer sure if the issue is actually with Play or with Lagom…
BR
Yanick