Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Support Janino in a native image #33758

Open
gdrouet opened this issue Jan 11, 2023 · 20 comments
Open

Support Janino in a native image #33758

gdrouet opened this issue Jan 11, 2023 · 20 comments
Labels
status: blocked An issue that's blocked on an external project change theme: aot An issue related to Ahead-of-time processing type: enhancement A general enhancement

Comments

@gdrouet
Copy link

gdrouet commented Jan 11, 2023

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 [email protected]/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 [email protected]/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.

@spring-projects-issues spring-projects-issues added the status: waiting-for-triage An issue we've not yet triaged label Jan 11, 2023
@philwebb philwebb added type: bug A general bug theme: aot An issue related to Ahead-of-time processing and removed status: waiting-for-triage An issue we've not yet triaged labels Jan 18, 2023
@philwebb philwebb added this to the 3.0.x milestone Jan 18, 2023
@wilkinsona wilkinsona changed the title Support Janino when building a native image Janino does not work when building a native image Feb 21, 2023
@wilkinsona
Copy link
Member

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.

@wilkinsona wilkinsona self-assigned this Feb 21, 2023
@hpoettker
Copy link
Contributor

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.

@wilkinsona
Copy link
Member

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.

@wilkinsona
Copy link
Member

wilkinsona commented Feb 21, 2023

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.

@wilkinsona wilkinsona added the for: team-meeting An issue we'd like to discuss as a team to make progress label Feb 21, 2023
@hpoettker
Copy link
Contributor

@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.

@gdrouet
Copy link
Author

gdrouet commented Feb 28, 2023

Do you have any workaround to write an equivalent programmatically and have a chance to make it work with spring native?

@wilkinsona
Copy link
Member

I'm afraid not. #25847 is tracking support for programmatic configuration of Logback.

@wilkinsona wilkinsona changed the title Janino does not work when building a native image Support Janino in a native image Jun 21, 2023
@wilkinsona wilkinsona added type: enhancement A general enhancement status: blocked An issue that's blocked on an external project change and removed type: bug A general bug for: team-meeting An issue we'd like to discuss as a team to make progress labels Jun 21, 2023
@wilkinsona wilkinsona modified the milestones: 3.0.x, General Backlog Jun 21, 2023
@wilkinsona
Copy link
Member

@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.

@ceki
Copy link

ceki commented Jun 21, 2023

@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.

@ceki
Copy link

ceki commented Jun 23, 2023

@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.

@wilkinsona
Copy link
Member

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.

@ceki
Copy link

ceki commented Jun 23, 2023

@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).

@drubio-tlnd
Copy link

drubio-tlnd commented Sep 1, 2023

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

@syedyusufh

This comment was marked as duplicate.

@guai
Copy link

guai commented Dec 26, 2023

would it work if logback supported condition in a simple predicate class instead of compiling expressions on the fly with janino?

@ceki
Copy link

ceki commented Dec 28, 2023

@guai Sounds like a good idea. I encourage you to file an issue with the logback project.

@ceki
Copy link

ceki commented Sep 9, 2024

@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.

@DarkAtra
Copy link

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):

@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:

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?

@ceki
Copy link

ceki commented Oct 16, 2024

@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.

@DarkAtra
Copy link

@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.

sure, here they are:

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
status: blocked An issue that's blocked on an external project change theme: aot An issue related to Ahead-of-time processing type: enhancement A general enhancement
Projects
None yet
Development

No branches or pull requests

10 participants