Logback's File Appender in build time causes failed native image creation #8
Description
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.
Activity
fabri1983 commentedon Sep 24, 2019
Native image generation forbids file descriptors because they won't exist at runtime.
Might be possible a fix or a dirty hack?
aclement commentedon 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 commentedon Oct 2, 2019
Hi. Thanks for the reply.
I've added several
Logback
's classes related toFile
andAppender
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.
jiangzx commentedon Feb 28, 2020
help!! any update on this issue?
sdeleuze commentedon Mar 30, 2020
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 fieldprivate 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 commentedon Apr 4, 2020
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.