Skip to content
This repository was archived by the owner on Feb 23, 2023. It is now read-only.
This repository was 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

Description

@fabri1983

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

Activity

fabri1983

fabri1983 commented on Sep 24, 2019

@fabri1983
Author

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

aclement

aclement commented on Oct 2, 2019

@aclement
Contributor

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

fabri1983 commented on Oct 2, 2019

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

jiangzx

jiangzx commented on Feb 28, 2020

@jiangzx

help!! any update on this issue?

self-assigned this
on Mar 30, 2020
added this to the v0.6.0 milestone on Mar 30, 2020
sdeleuze

sdeleuze commented on Mar 30, 2020

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

modified the milestones: v0.6.0, v0.7.0 on Mar 30, 2020
sdeleuze

sdeleuze commented on Apr 4, 2020

@sdeleuze
Contributor

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

Type

No type

Projects

No projects

Relationships

None yet

    Development

    No branches or pull requests

      Participants

      @sdeleuze@aclement@fabri1983@jiangzx

      Issue actions

        Logback's File Appender in build time causes failed native image creation · Issue #8 · spring-attic/spring-native