When building a native image with Spring Boot Maven plugin, Logback configuration relying on Janino leads to an error.
For instance, if we add to the logback-spring.xml file the following if statement:
<if condition='isDefined("ENV")'>
<then>
<appender-ref ref="CONSOLE_JSON"/>
</then>
<else>
<appender-ref ref="CONSOLE_LOCAL"/>
</else>
</if>
Then running a native image lead to this error:
Logging system failed to initialize using configuration from 'null'
java.util.EmptyStackException
at java.base@17.0.5/java.util.Stack.peek(Stack.java:101)
at ch.qos.logback.core.model.processor.ModelInterpretationContext.peekModel(ModelInterpretationContext.java:84)
at ch.qos.logback.core.model.processor.conditional.ElseModelHandler.handle(ElseModelHandler.java:45)
at ch.qos.logback.core.model.processor.DefaultProcessor.secondPhaseTraverse(DefaultProcessor.java:241)
at ch.qos.logback.core.model.processor.DefaultProcessor.secondPhaseTraverse(DefaultProcessor.java:253)
at ch.qos.logback.core.model.processor.DefaultProcessor.secondPhaseTraverse(DefaultProcessor.java:253)
at ch.qos.logback.core.model.processor.DefaultProcessor.secondPhaseTraverse(DefaultProcessor.java:253)
at ch.qos.logback.core.model.processor.DefaultProcessor.traversalLoop(DefaultProcessor.java:90)
at ch.qos.logback.core.model.processor.DefaultProcessor.process(DefaultProcessor.java:106)
at ch.qos.logback.core.joran.GenericXMLConfigurator.processModel(GenericXMLConfigurator.java:200)
at org.springframework.boot.logging.logback.SpringBootJoranConfigurator.processModel(SpringBootJoranConfigurator.java:122)
at org.springframework.boot.logging.logback.SpringBootJoranConfigurator.configureUsingAotGeneratedArtifacts(SpringBootJoranConfigurator.java:115)
at org.springframework.boot.logging.logback.LogbackLoggingSystem.initializeFromAotGeneratedArtifactsIfPossible(LogbackLoggingSystem.java:210)
at org.springframework.boot.logging.logback.LogbackLoggingSystem.initialize(LogbackLoggingSystem.java:187)
at org.springframework.boot.context.logging.LoggingApplicationListener.initializeSystem(LoggingApplicationListener.java:332)
at org.springframework.boot.context.logging.LoggingApplicationListener.initialize(LoggingApplicationListener.java:298)
at org.springframework.boot.context.logging.LoggingApplicationListener.onApplicationEnvironmentPreparedEvent(LoggingApplicationListener.java:246)
at org.springframework.boot.context.logging.LoggingApplicationListener.onApplicationEvent(LoggingApplicationListener.java:223)
at org.springframework.context.event.SimpleApplicationEventMulticaster.doInvokeListener(SimpleApplicationEventMulticaster.java:176)
at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:169)
at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:143)
at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:131)
at org.springframework.boot.context.event.EventPublishingRunListener.multicastInitialEvent(EventPublishingRunListener.java:136)
at org.springframework.boot.context.event.EventPublishingRunListener.environmentPrepared(EventPublishingRunListener.java:81)
at org.springframework.boot.SpringApplicationRunListeners.lambda$environmentPrepared$2(SpringApplicationRunListeners.java:64)
at java.base@17.0.5/java.lang.Iterable.forEach(Iterable.java:75)
at org.springframework.boot.SpringApplicationRunListeners.doWithListeners(SpringApplicationRunListeners.java:118)
at org.springframework.boot.SpringApplicationRunListeners.doWithListeners(SpringApplicationRunListeners.java:112)
at org.springframework.boot.SpringApplicationRunListeners.environmentPrepared(SpringApplicationRunListeners.java:63)
at org.springframework.boot.SpringApplication.prepareEnvironment(SpringApplication.java:352)
at org.springframework.boot.SpringApplication.run(SpringApplication.java:303)
at org.springframework.boot.SpringApplication.run(SpringApplication.java:1302)
at org.springframework.boot.SpringApplication.run(SpringApplication.java:1291)
Note that a fat-jar run with -Dspring.aot.enabled=true does not help to reproduce the issue.
It would be great to have such support for native image.
Comment From: wilkinsona
https://stackoverflow.com/questions/75514151/spring-boot-native-image-does-not-print-logs-when-logback-is-configured-with-con contains another sample that exhibits slightly different faulty behaviour – this sample starts successfully but no logging output is produced.
Comment From: hpoettker
In the example from the stackoverflow question, I also get the exception from the original post if no metadata is added to src/main/resources/META-INF/native-image.
Comment From: wilkinsona
Unfortunately, supporting Janino is non-trivial. It relies on generating ch.qos.logback.core.joran.conditional.Condition implementations at runtime, something that Graal does not support. Spring Native hacked around this with a substitution. This option is not open to us. We do not use substitutions in Boot as the Graal team have been clear that they should not be used.
One option that we could explore is generating the Condition implementations at build time, including them in the native image and then reusing these pre-generated classes at runtime. This is what Framework does for CGLib-based proxies. This may not be possible without changes to Logback if the necessary hook points are not available.
Comment From: wilkinsona
I've prototyped something in this branch. It's not a lot of code, but I'm not happy with AotIfModelHandler. It duplicates much of the logic in Logback's IfModelHandler which would be at risk of falling out of sync. I'd like to discuss our options with the rest of the team. My feeling is that we won't be able to do something here without some changes to Logback.
Comment From: hpoettker
@wilkinsona Thanks for implementing #34315 so quickly! The sample application from the stackoverflow question now fails early and logs a meaningful exception. I've added it to the SO question.
Comment From: gdrouet
Do you have any workaround to write an equivalent programmatically and have a chance to make it work with spring native?
Comment From: wilkinsona
I'm afraid not. https://github.com/spring-projects/spring-boot/issues/25847 is tracking support for programmatic configuration of Logback.
Comment From: wilkinsona
@ceki would you consider making some changes to IfModelHandler to make it more Graal-friendly? We'd like to be able to capture the class files that it creates so that they can be contributed to a GraalVM native image. Then, when the image is being executed, we'd like to be able to provide those classes to the handler rather than it compiling them again.
Comment From: ceki
@wilkinsona Sure, I am open to changes. I have looked at your efforts to support logback with GraalVM which are quite impressive.
For your information, I have started to explore a path for supporting GraalVM which you might find interesting:
Note: experimental changes in 1.4.9 (commit bd11e72017941331f2c3ba5101429359aced5a47 not yet released)
- JoranConfigurator is invoked by reflection and no longer as a service.
- JoranConfigurator now supports the
<serializeModel file="...."/>directive in logback.xml to dump/serialize the model it created into an ObjectOutputStream file with an .smo extension. - SerializedModelConfigurator searches for serialized model files (.smo extension) and configures logback if a logback.smo or logback-test.smo file is found.
- SerializedModelConfigurator is invoked as a configurator service. This happens before JoranConfigurator is invoked via serialization.
Anyway, I am still experimenting and am not sure of the results, that is whether this will work with GraalVM without the need for an XML parser.
Coming back to your original question, I understand that the experimental approach outlined above is different than the question raised by Janino.
Update: the strategy outlined above is verified to work in a GraalVM native-image, at least in simple scenarios.
Comment From: ceki
@wilkinsona As of commit c440e08b, logback supports loading a model configuration file without ever loading JoranConfigurator and without including java.xml in a native image. I have verified this to work with GraalVM.
Comment From: wilkinsona
That sounds great. Thanks, @ceki. Are Logback snapshots published anywhere? I'd like to give the new serialisation support a try and see if we can rip out the stuff that I wrote.
Comment From: ceki
@wilkinsona Logback snapshots are not published. You would need to check out from github source and build at your end using the JDK 11+ and Maven.
I will be documenting the procedure for using serialized model (SMO) files shortly. The only "tricky" part is to remember to add <serializeModel file="${aVariablePointingToADestinationFile}"/> directive in logback.xml.
Please note this is still work in progress. More testing is required before public release.
Just fixed a silly bug this morning (24th of June).
Comment From: drubio-tlnd
Hey, did the use of scmo file allows to use the janino library with conditions ?
I currently have a logback-spring.xml that looks like that:
<?xml version="1.0" encoding="UTF-8"?>
<configuration debug="false">
<serializeModel file="src/main/resources/logback.scmo"/>
<include resource="org/springframework/boot/logging/logback/defaults.xml"/>
<include resource="org/springframework/boot/logging/logback/console-appender.xml"/>
<property name="LOGGING_LEVEL" value="${LOGGING_LEVEL:-INFO}"/>
<property name="CONSOLE_LOG_THRESHOLD" value="${CONSOLE_LOG_THRESHOLD:-INFO}"/>
<springProfile name="!dev">
<if condition='p("LOGGING_LAYOUT").toUpperCase().equals("TEXT")'>
<then>
<!-- use the default TEXT layout -->
</then>
<else>
<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
<filter class="ch.qos.logback.classic.filter.ThresholdFilter">
<level>${CONSOLE_LOG_THRESHOLD}</level>
</filter>
</appender>
<logger name="reactor.netty.http.server.AccessLog" level="INFO" additivity="false">
<appender-ref ref="CONSOLE"/>
</logger>
</else>
</if>
</springProfile>
<root level="${LOGGING_LEVEL}">
<appender-ref ref="CONSOLE"/>
</root>
</configuration>
1- When not using scmo file, I keep having EmptyStackException when running the native executable (following gradle nativeCompile command).
2- While when using the scmo file, I have errors like:
InvalidClassException: Unauthorized deserialization attempt; org.springframework.boot.logging.logback.SpringProfileModel
InvalidClassException: Unauthorized deserialization attempt; ch.qos.logback.core.model.conditional.IfModel
This error comes from ch.qos.logback.classic.joran.SerializedModelConfigurator following instruction:
HardenedModelInputStream hmis = new HardenedModelInputStream(is);
Model model = (Model) hmis.readObject();
I cannot figure out if there is something wrong in my native configuration, or if it's related to ch.qos.logback.classic.net.server.HardenedModelInputStream.getWhitelist() method which does not contain these 2 classes
Comment From: syedyusufh
@ceki could you please tell us the way to use logback + janino in a Spring Boot native image?
Comment From: guai
would it work if logback supported condition in a simple predicate class instead of compiling expressions on the fly with janino?
Comment From: ceki
@guai Sounds like a good idea. I encourage you to file an issue with the logback project.
Comment From: ceki
@gdrouet FYI, logback-tyler already translates janono-expressions into Java. It seems to me that the output generated logbaclk-tyler is an auto-loadable Configurator and shoulfd be quite suitable for a GraalVM application.
Also, the next version of logback-tyler will support PropertiesConfigurator (new in logback 1,5,8) which allows setting logger levels from a properties file.
Comment From: DarkAtra
hey @ceki, first of all: thanks for all your great work on logback-classic and logback-tyler.
I just gave it a try and quickly found that the following requirement is not met in case of Spring Boot Applications:
At runtime, TylerConfigurator does not have any additional dependencies other than logback-classic version 1.5.10.
I tried using version 0.9 of logback-tyler and setting the logback.version for our Spring Boot project to 1.5.11. I then ran logback-tyler for our config file. This is a very simplified version of it:
<?xml version="1.0" encoding="UTF-8"?>
<configuration>
<springProperty scope="context" name="consoleEnabled" source="logging.console.enabled"/>
<if condition='${consoleEnabled}'>
<then>
<include resource="logback-console-appender.xml"/>
<root level="info">
<appender-ref ref="CONSOLE"/>
</root>
</then>
</if>
</configuration>
This is the resulting code from logback-tyler (which does not compile): ```java @Override public Configurator.ExecutionStatus configure(LoggerContext loggerContext) { setContext(loggerContext); if(${consoleEnabled}) { // <-------- 1. issue: broken if condition IncludeModel includeModel = new IncludeModel(); includeModel.setResource(subst("logback-console-appender.xml")); IncludeModelHandler includeModelHandler = new IncludeModelHandler(context); try { Model modelFromIncludedFile = includeModelHandler.buildModelFromIncludedFile(this, includeModel); processModelFromIncludedFile(modelFromIncludedFile); } catch(ModelHandlerException e) { addError("Failed to process IncludeModelHandler", e); } Logger logger_ROOT = setupLogger("ROOT", "info", null); logger_ROOT.addAppender(appenderCONSOLE); // <-------- 2. issue: broken appender reference } return ExecutionStatus.DO_NOT_INVOKE_NEXT_IF_ANY; }
1. conditions with spring expressions are not converted correctly - probably because logback-tyler doesn't know anything about spring. Is there anything that spring-boot could do to participate in the conversion for spring specific features?
2. appenders defined in an included file are not correctly referenced (can also be seen in the example above) - this seems to be a bug in logback-tyler and is not related to Spring Boot
Also, the logback-tyler readme claims that:
> Running TylerConfigurator does not require XML parsers and usually executes noticeably faster than JoranConfigurator, logback's XML configurator.
However, `<include resource="logback-console-appender.xml"/>` is translated to:
```java
IncludeModel includeModel = new IncludeModel();
includeModel.setResource(subst("logback-console-appender.xml"));
IncludeModelHandler includeModelHandler = new IncludeModelHandler(context);
try {
Model modelFromIncludedFile = includeModelHandler.buildModelFromIncludedFile(this, includeModel);
processModelFromIncludedFile(modelFromIncludedFile);
} catch(ModelHandlerException e) {
addError("Failed to process IncludeModelHandler", e);
}
To me it seems like includeModelHandler.buildModelFromIncludedFile(this, includeModel) uses an XML parser internally and the referenced xml file is probably also allowed to use conditions which then also requires Janino (an issue with GraalMV). Is there any way to configure logback-tyler so that it also resolves and translates included files?
Comment From: ceki
@DarkAtra Since the issue you describe is mostly logback-tyler related, would you mind creating a new issue in the logback project?
Note at translation time logback-tyler usually does not have access to the included file. Thus, it should not be expected to translate the included file. The translation that logback-tyler produces currently seems likely to work at runtime when TylerConfigurator is invoked to configure logback.
Comment From: DarkAtra
@DarkAtra Since the issue you describe is mostly logback-tyler related, would you mind creating a new issue in the logback project?
Note at translation time logback-tyler usually does not have access to the included file. Thus, it should not be expected to translate the included file. The translation that logback-tyler produces currently seems likely to work at runtime when
TylerConfiguratoris invoked to configure logback.
sure, here they are: * https://github.com/qos-ch/logback/issues/875 * https://github.com/qos-ch/logback/issues/874 * https://github.com/qos-ch/logback/issues/873
Comment From: philwebb
As part of discussing #44235 in our team call today Janino native image support came up again. After some consideration, we've decided that we won't have the bandwidth to attempt to fix this directly in Spring Boot. We're going to treat Janino support in the same way as we do many other libraries, and rely on upstream native image support. This probably means https://github.com/qos-ch/logback/issues/757 or update in Janino itself.
Another future option might be to combine code generated by https://github.com/qos-ch/logback-tyler with whatever fix we can eventually provide for #25847.
I'm sorry we don't have more time to find a solution for folks watching this issue.