Skip to content
This repository has been archived by the owner on Feb 23, 2023. It is now read-only.

Logback's File Appender in build time causes failed native image creation #8

Closed
fabri1983 opened this issue Sep 24, 2019 · 6 comments
Closed

Logback's File Appender in build time causes failed native image creation #8

fabri1983 opened this issue Sep 24, 2019 · 6 comments
Assignees
@sdeleuze
Labels
type: compatibility Native image compatibility issue
Milestone
0.6.0

Comments

@fabri1983
Copy link

Hi. I'm working on a project involving Spring Boot with WebSockets, and using Logback Classic as the logging implementation API.
The project is packaged on a war file with an embedded Tomcat.

Here are the logging dependencies in pom.xml:

		<!-- Logging APIs -->
		<dependency>
			<groupId>org.slf4j</groupId>
			<artifactId>log4j-over-slf4j</artifactId>
		</dependency>
		<dependency>
			<groupId>org.slf4j</groupId>
			<artifactId>jcl-over-slf4j</artifactId>
		</dependency>
		<dependency>
			<groupId>org.slf4j</groupId>
			<artifactId>jul-to-slf4j</artifactId>
		</dependency>
		<dependency>
			<groupId>ch.qos.logback</groupId>
			<artifactId>logback-classic</artifactId>
		</dependency>

and this is the logback.xml located at src/main/resources

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE xml>
<configuration debug="false" scan="false">
	<statusListener class="ch.qos.logback.core.status.NopStatusListener" />
	<appender name="FILE"
		class="ch.qos.logback.core.rolling.RollingFileAppender">
		<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
			<!-- Daily rollover -->
			<fileNamePattern>logs/signaling-%d{yyyyMMdd}.log</fileNamePattern>
			<!-- Keep 7 days' worth of history -->
			<maxHistory>7</maxHistory>
			<!-- logs up to a maximum size of 1GB -->
			<totalSizeCap>1GB</totalSizeCap>
		</rollingPolicy>
		<encoder>
			<pattern>%date{ISO8601} %-5level [%t] %X{uid} %c{0}: %msg%n</pattern>
		</encoder>
	</appender>
	<root level="INFO">
		<appender-ref ref="FILE" />
	</root>
</configuration>

As you can see above, the logging configuration file defines a File Appender (specifically the RollingFileAppender) which will create a file when the logging backend is instanciated at boot time.

The problem is that I'm not able to create a native image with file creation during native image build time.

After collecting every class involved in build time for the reflective instantiation of logback's file appender and put them into respective Spring Graal Feature files:
initialization.json, proxies.json, reflect.json, resources.json
(see attached file native-image-missing-features.txt)
I get the next message:

[signaling.war:3400]     analysis: 853,104.17 ms
Error: Detected a FileDescriptor in the image heap. File descriptors opened during image generation are no longer open at image run time, and the files might not even be present anymore at image run time. Object has been initialized without the native-image initialization instrumentation and the stack trace can't be tracked. The object was probably created by a class initializer and is reachable from a static field. You can request class initialization at image run time by using the option --initialize-at-build-time=<class-name>. Or you can write your own initialization methods and call them explicitly from your main entry point.
Detailed message:
Trace:  object java.io.FileOutputStream
        object ch.qos.logback.core.recovery.ResilientFileOutputStream
        object ch.qos.logback.core.rolling.RollingFileAppender
        object ch.qos.logback.core.status.InfoStatus
        object java.lang.Object[]
        object java.util.ArrayList
        object ch.qos.logback.core.BasicStatusManager
        object ch.qos.logback.classic.LoggerContext
        object org.slf4j.impl.StaticLoggerBinder
        field org.slf4j.impl.StaticLoggerBinder.SINGLETON

Which is due to the attempt of a file creation given the File Appender configured in logback.properties.
See file attached file native-image-missing-features.txt to get an idea of all the missing features I had to add.

Is this caused by a misconfiguration on my project? Or is it a missing feature to allow logback's file appender correctly create a file descriptor in build time?

Aside note: if I use an empty logback.xml (I mean no appenders) then the error message disappears.

native-image-missing-features.txt
@fabri1983
Copy link
Author

Native image generation forbids file descriptors because they won't exist at runtime.
Might be possible a fix or a dirty hack?

@aclement
Copy link
Contributor

aclement commented Oct 2, 2019

Hey. If I were exploring this, I'd look at where the FileAppender is being created and see if I can push that to runtime initialization in the initialization config file (maybe you've tried that, I haven't had a chance to dig through yet). However, I know sometimes with logging just touching any old class that has logging causes the initialization of a 'bunch of stuff' that might be pulling this in early anyway.

If initialization can't control it you can look at using a substitution to patch behaviour (see the source files in the project that start Target_). Depending on how the file descriptor is opened you might be able to patch it. We haven't gone deep on logback yet I'm afraid. I haven't hit a FileDescriptor in heap at image build time situation before either (yet) so haven't got a standard approach to dealing with them.

@fabri1983
Copy link
Author

Hi. Thanks for the reply.

I've added several Logback's classes related to File and Appender in the initialization.json file.
As you mentioned, it might be some other classes get also initialized and so these have to be added for build-time initialization. Although, I couldn't get any meaningful stacktrace reporting a class to possible be added for build-time initialization, as I got in the past. It seems I've added all the classes involved in the creation of the RollingFileAppender for build-time initialization (see attached native-image-missing-features in first post).
Sometimes if I run the native image generation process again it shows a stacktrace with a new class intended to be created through reflection that wasn't in the build-time initialization list.

On the other hand, the use of substitutions might help. I'll try to take a look on that.
Thanks again.

@sbchapin sbchapin mentioned this issue Nov 21, 2019
Open
@sdeleuze sdeleuze added status: waiting-for-triage An issue we've not yet triaged or decided on type: compatibility Native image compatibility issue labels Dec 2, 2019
@jiangzx
Copy link

jiangzx commented Feb 28, 2020

help!! any update on this issue?

@sdeleuze sdeleuze self-assigned this Mar 30, 2020
@sdeleuze sdeleuze added this to the v0.6.0 milestone Mar 30, 2020
@sdeleuze sdeleuze removed the status: waiting-for-triage An issue we've not yet triaged or decided on label Mar 30, 2020
@sdeleuze
Copy link
Contributor

What happens here is that BeanUtils (like in 183 other classes in Spring Framework, and likely others in Spring Boot, Data, etc.) there is a static field private static final Log logger = LogFactory.getLog(BeanUtils.class); that get initialized at build time, triggering the initialization of the logging system and transitively the creation of the log file at build time which is not what we want.

One way to fix that would be performing late initialization of the logging subsystem in Spring. The other would be to switch back to runtime initialization by default.

We need to evaluate if they are other use cases (Socket?), if that's mainly limited to Spring (likely since Spring bootstrap the application) and if other Spring portfolio projects would be ok to switch to lazy logging system initialization or not (let start by Boot, Data and Security).

@sdeleuze sdeleuze modified the milestones: v0.6.0, v0.7.0 Mar 30, 2020
@sdeleuze
Copy link
Contributor

sdeleuze commented Apr 4, 2020 •
edited

After more thoughts and discussion within the team, we have decided to move toward runtime class initialization to increase compatibility and avoid this kind of non trivial issue. I have updated non Netty based samples to use runtime init. We will update Netty samples as well only in 0.7 since it is currently not possible to use Netty with runtime init.

I have updated our documentation accordingly to provide guidance about that.

@sdeleuze sdeleuze closed this as completed Apr 4, 2020
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees

@sdeleuze sdeleuze

Labels
type: compatibility Native image compatibility issue
Milestone
0.6.0
Development

No branches or pull requests
4 participants
@sdeleuze @aclement @fabri1983 @jiangzx