Logging configuration with custom properties


(Yanick Salzmann) #1

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


(Marcos Pereira) #2

Hi @yanick.salzmann,

I’m moving this question to #lagom since it looks like it is what you are using.


About the question, logging configuration is the first thing that happens when starting an application, even before reading configuration. That is because we want to also log all the initialization steps, so logging starts first.

If you want to customize how the logging framework is initialized, take a look at the following docs:

https://www.lagomframework.com/documentation/1.4.x/java/SettingsLogger.html#Using-a-Custom-Logging-Framework

Best.